dhclient doesn't like the school network?

[Zelmo3]

At home I use static network addressing on my Linux laptop for convenience. The school's wireless network uses DHCP, so I have a script to bring the wireless interface down and then back up with DHCP and the correct credentials for wireless access. After a varying amount of time (ranges from as long as a minute or two to as short as not even finishing the post-ifup network stuff), the computer locks up hard--no mouse movement and no keyboard response, and I have to power down to get out of it.

It's been doing this all semester. To see if it's a general problem with DHCP, I brought down the interface while at home and brought it back up with DHCP. It works fine at home, even if I tunnel all traffic through the school's VPN. So it looks like dhclient has an issue with the school's DHCP server (which worked well enough in the spring), and I don't know where to look for signs of a solution.

Googling returned one situation that resembled mine, and it wasn't resolved. Anyone have some ideas?

 

[n0cmonkey]

Anything in the logs?

 

[Zelmo3]

I found these lines in /var/log/messages:

Nov 17 09:37:39 localhost kernel: [4294886.533000] Process dhclient-script (pid: 7616, threadinfo=c9190000 task=d42edac0)
Nov 17 09:37:39 localhost kernel: [4294886.533000] Stack: 00000000 bf9e252c 00000000 c8c66a90 c90d2f60 c8c66a90 dbee4440 c0160643
Nov 17 09:37:39 localhost kernel: [4294886.533000] ffffffff c90d2f60 00000000 d1e79930 00000008 c0160750 ffffffff c90d2f60
Nov 17 09:37:39 localhost kernel: [4294886.533000] 00000000 c01555b6 c8c66a90 c90d2f60 00000000 00000000 c91ab164 c90d2f60
Nov 17 09:37:39 localhost kernel: [4294886.533000] Call Trace:
Nov 17 09:37:39 localhost kernel: [4294886.533000] [pipe_write_fasync+62/85] pipe_write_fasync+0x3e/0x55
Nov 17 09:37:39 localhost kernel: [4294886.533000] [pipe_write_release+31/63] pipe_write_release+0x1f/0x3f
Nov 17 09:37:39 localhost kernel: [4294886.533000] [__fput+338/385] __fput+0x152/0x181
Nov 17 09:37:39 localhost kernel: [4294886.533000] [filp_close+82/150] filp_close+0x52/0x96
Nov 17 09:37:39 localhost kernel: [4294886.533000] [sys_close+77/92] sys_close+0x4d/0x5c
Nov 17 09:37:39 localhost kernel: [4294886.533000] [sysenter_past_esp+84/117] sysenter_past_esp+0x54/0x75

I can't make sense of any of them. Interestingly, dhclient is only mentioned once in yesterday's log messages, though I restarted the computer four times while at school.

/var/log/syslog.0 has more detailed stuff, but nothing that indicates the trouble spot. Restarts appear at various places; the earliest it happens is right after the interface is bound to an address, the latest it happens is a bit after a pptp tunnel is set up (within a minute or two of getting an address).

What other logs should I be looking at?

 

[bersl2]

The kernel is panicking. Hmm...

I guess dhclient is exposing a bug in the wireless drivers. Give us some of the non-repetitive contents of /var/log/syslog*

 

[Zelmo3]

A few lines from the bootup process:

Nov 17 09:24:20 localhost kernel: [4294717.953000] ndiswrapper version 1.1 loaded (preempt=no,smp=no)
Nov 17 09:24:20 localhost kernel: [4294718.040000] ndiswrapper: driver bcmwl5 (Broadcom,06/13/2003, 3.20.23.0) loaded
Nov 17 09:24:20 localhost kernel: [4294718.040000] ACPI: PCI Interrupt 0000:00:0c.0[A] -> Link [LNK2] -> GSI 10 (level, low) -> IRQ 10
Nov 17 09:24:20 localhost kernel: [4294718.047000] ndiswrapper: using irq 10
Nov 17 09:24:20 localhost kernel: [4294718.619000] wlan0: ndiswrapper ethernet device 00:90:96:65:5b😀6 using driver bcmwl5, configuration file 14E4:4320.5.conf
Nov 17 09:24:20 localhost kernel: [4294718.619000] wlan0: encryption modes supported: WEP, WPA with TKIP, WPA with AES/CCMP

...and a bigger block ranging from the first mention of networking until the next restart:

Nov 17 09:25:56 localhost postfix/master[6884]: reload configuration /etc/postfix
Nov 17 09:25:56 localhost dhclient: Internet Systems Consortium DHCP Client V3.0.2
Nov 17 09:25:56 localhost dhclient: Copyright 2004 Internet Systems Consortium.
Nov 17 09:25:56 localhost dhclient: All rights reserved.
Nov 17 09:25:56 localhost dhclient: For info, please visit http://www.isc.org/products/DHCP
Nov 17 09:25:56 localhost dhclient:
Nov 17 09:25:57 localhost kernel: [4294900.831000] NET: Registered protocol family 17
Nov 17 09:25:57 localhost dhclient: Listening on LPF/wlan0/00:90:96:65:5b😀6
Nov 17 09:25:57 localhost dhclient: Sending on LPF/wlan0/00:90:96:65:5b😀6
Nov 17 09:25:57 localhost dhclient: Sending on Socket/fallback
Nov 17 09:25:57 localhost kernel: [4294901.314000] wlan0 (WE) : Wireless Event too big (305)
Nov 17 09:25:58 localhost dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 5
Nov 17 09:25:58 localhost kernel: [4294902.555000] Unable to handle kernel paging request at virtual address 66692f80
Nov 17 09:25:58 localhost kernel: [4294902.555000] printing eip:
Nov 17 09:25:58 localhost kernel: [4294902.555000] c0166477
Nov 17 09:25:58 localhost kernel: [4294902.555000] *pde = 00000000
Nov 17 09:25:58 localhost kernel: [4294902.555000] Oops: 0000 [#1]
Nov 17 09:25:58 localhost kernel: [4294902.555000] Modules linked in: af_packet radeon drm rfcomm l2cap bluetooth powernow_k7 cpufreq_userspace cpufreq_stats freq_table cpufreq_powersave cpufreq_ondemand cpufreq_conservative pcmcia nfsd exportfs lockd sunrpc video tc1100_wmi sony_acpi pcc_acpi hotkey dev_acpi i2c_acpi_ec button battery container ac ndiswrapper pcspkr rtc i2c_ali1535 i2c_ali15x3 i2c_core ohci1394 yenta_socket rsrc_nonstatic pcmcia_core snd_ali5451 snd_ac97_codec snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd soundcore snd_page_alloc shpchp pci_hotplug ati_agp agpgart dm_mod joydev tsdev evdev sr_mod sbp2 scsi_mod ieee1394 psmouse mousedev parport_pc lp parport md ext3 jbd mbcache thermal processor fan b44 mii ehci_hcd ohci_hcd usbcore ide_cd cdrom ide_disk ide_generic alim15x3 ide_core unix vesafb capability commoncap vga16fb vgastate softcursor cfbimgblt cfbfillrect cfbcopyarea fbcon tileblit font bitblit
Nov 17 09:25:58 localhost kernel: [4294902.555000] CPU: 0
Nov 17 09:25:58 localhost kernel: [4294902.555000] EIP: 0060:[fasync_helper+52/215] Tainted: P VLI
Nov 17 09:25:58 localhost kernel: [4294902.555000] EFLAGS: 00210006 (2.6.12-9-k7)
Nov 17 09:25:58 localhost kernel: [4294902.555000] EIP is at fasync_helper+0x34/0xd7
Nov 17 09:25:58 localhost kernel: [4294902.555000] eax: ffffffff ebx: 00000000 ecx: d15fa008 edx: 66692f74
Nov 17 09:25:58 localhost kernel: [4294902.555000] esi: c9138100 edi: d16b4330 ebp: 00000000 esp: cedb7f24
Nov 17 09:25:58 localhost kernel: [4294902.555000] ds: 007b es: 007b ss: 0068
Nov 17 09:25:58 localhost kernel: [4294902.555000] Process kded (pid: 7227, threadinfo=cedb6000 task=cec105e0)
Nov 17 09:25:58 localhost kernel: [4294902.555000] Stack: c016cf9c 00000001 00000000 d295ad58 c9138100 d295ad58 dbee4440 c0160643
Nov 17 09:25:58 localhost kernel: [4294902.555000] ffffffff c9138100 00000000 d16b4330 00000008 c0160750 ffffffff c9138100
Nov 17 09:25:58 localhost kernel: [4294902.555000] 00000000 c01555b6 d295ad58 c9138100 00000000 00000000 d2bfb6b4 c9138100
Nov 17 09:25:58 localhost kernel: [4294902.555000] Call Trace:
Nov 17 09:25:58 localhost kernel: [4294902.555000] [clear_inode+17/286] clear_inode+0x11/0x11e
Nov 17 09:25:58 localhost kernel: [4294902.555000] [pipe_write_fasync+62/85] pipe_write_fasync+0x3e/0x55
Nov 17 09:25:58 localhost kernel: [4294902.555000] [pipe_write_release+31/63] pipe_write_release+0x1f/0x3f
Nov 17 09:25:58 localhost kernel: [4294902.555000] [__fput+338/385] __fput+0x152/0x181
Nov 17 09:25:58 localhost kernel: [4294902.555000] [filp_close+82/150] filp_close+0x52/0x96
Nov 17 09:25:58 localhost kernel: [4294902.555000] [sys_close+77/92] sys_close+0x4d/0x5c
Nov 17 09:25:58 localhost kernel: [4294902.555000] [sysenter_past_esp+84/117] sysenter_past_esp+0x54/0x75
Nov 17 09:25:58 localhost kernel: [4294902.555000] Code: 24 28 89 5c 24 0c 31 db 85 ed 89 74 24 10 89 7c 24 14 8b 74 24 24 8b 7c 24 2c c7 44 24 08 00 00 00 00 75 52 fa 89 f9 8b 17 eb 0b <39> 72 0c 74 68 8d 4a 08 8b 52 08 85 d2 75 f1 85 ed 74 1f c7 03
Nov 17 09:25:59 localhost dhclient: DHCPOFFER from 172.30.1.1
Nov 17 09:25:59 localhost dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Nov 17 09:25:59 localhost dhclient: DHCPACK from 172.30.1.1
Nov 17 09:25:59 localhost dhclient: bound to 172.30.110.105 -- renewal in 5757 seconds.
Nov 17 09:25:59 localhost postfix/master[6884]: reload configuration /etc/postfix
Nov 17 09:28:51 localhost kernel: [4294902.555000] <4>psmouse.c: bad data from KBC - timeout
Nov 17 09:30:54 localhost anacron[7513]: Job `cron.daily' started
Nov 17 09:30:54 localhost anacron[7731]: Updated timestamp for job `cron.daily' to 2005-11-17
Nov 17 09:30:56 localhost hpiod: unable to ParDevice:😱pen hp:/par/ANY?device=/dev/parport0: No such file or directory: io/hpiod/ppdevice.cpp 827
Nov 17 09:30:56 localhost hpiod: unable to ParDevice:😱pen hp:/par/ANY?device=/dev/parport1: No such file or directory: io/hpiod/ppdevice.cpp 827
Nov 17 09:30:56 localhost hpiod: unable to ParDevice:😱pen hp:/par/ANY?device=/dev/parport2: No such file or directory: io/hpiod/ppdevice.cpp 827
Nov 17 09:30:56 localhost hpiod: unable to ParDevice:😱pen hp:/par/ANY?device=/dev/parport3: No such file or directory: io/hpiod/ppdevice.cpp 827
Nov 17 09:32:27 localhost kernel: [4295291.716000] CSLIP: code copyright 1989 Regents of the University of California
Nov 17 09:32:28 localhost kernel: [4295291.758000] PPP generic driver version 2.4.2
Nov 17 09:32:28 localhost pppd[7865]: pppd 2.4.3 started by root, uid 0
Nov 17 09:32:28 localhost pppd[7865]: Using interface ppp0
Nov 17 09:32:28 localhost pppd[7865]: Connect: ppp0 <--> /dev/pts/2
Nov 17 09:32:28 localhost pptp[7876]: anon log[main😛ptp.c:243]: The synchronous pptp option is NOT activated
Nov 17 09:32:28 localhost pptp[7896]: anon log[ctrlp_rep😛ptp_ctrl.c:243]: Sent control packet type is 1 'Start-Control-Connection-Request'
Nov 17 09:32:28 localhost pptp[7896]: anon log[ctrlp_disp😛ptp_ctrl.c:721]: Received Start Control Connection Reply
Nov 17 09:32:28 localhost pptp[7896]: anon log[ctrlp_disp😛ptp_ctrl.c:755]: Client connection established.
Nov 17 09:32:29 localhost pptp[7896]: anon log[ctrlp_rep😛ptp_ctrl.c:243]: Sent control packet type is 7 'Outgoing-Call-Request'
Nov 17 09:32:29 localhost pptp[7896]: anon log[ctrlp_disp😛ptp_ctrl.c:841]: Received Outgoing Call Reply.
Nov 17 09:32:29 localhost pptp[7896]: anon log[ctrlp_disp😛ptp_ctrl.c:880]: Outgoing call established (call ID 0, peer's call ID 11341).
Nov 17 09:32:29 localhost pptp[7896]: anon log[ctrlp_disp😛ptp_ctrl.c:933]: PPTP_SET_LINK_INFO received from peer_callid 0
Nov 17 09:32:29 localhost pptp[7896]: anon log[ctrlp_disp😛ptp_ctrl.c:936]: send_accm is 00000000, recv_accm is FFFFFFFF
Nov 17 09:32:29 localhost pptp[7896]: anon warn[ctrlp_disp😛ptp_ctrl.c:939]: Non-zero Async Control Character Maps are not supported!
Nov 17 09:32:29 localhost kernel: [4295293.382000] MPPE/MPPC encryption/compression module registered
Nov 17 09:32:29 localhost pppd[7865]: MPPE 128-bit stateless compression enabled
Nov 17 09:32:31 localhost pppd[7865]: Cannot determine ethernet address for proxy ARP
Nov 17 09:32:31 localhost pppd[7865]: local IP address 144.80.110.146
Nov 17 09:32:31 localhost pppd[7865]: remote IP address 144.80.110.51
Nov 17 09:32:31 localhost pppd[7865]: primary DNS address 144.80.128.27
Nov 17 09:32:31 localhost pppd[7865]: secondary DNS address 144.80.128.6
Nov 17 09:32:32 localhost postfix/master[6884]: reload configuration /etc/postfix
Nov 17 09:36:14 localhost syslogd 1.4.1#17ubuntu3: restart.

 

[n0cmonkey]

First, I'd try getting a decent wireless card and drop the broadcom/ndiswrapper crap.

 

[Nothinman]

Nov 17 09:24:20 localhost kernel: [4294717.953000] ndiswrapper version 1.1 loaded (preempt=no,smp=no)

Good luck with that, running Windows drivers in Linux has always seemed dumb to me.

Wireless Event too big (305)

That seems to be where things start to fall apart, but I have no idea whether it's a problem with ndiswrapper or the Windows driver it's wrapping.