Re: orinoco_cs module and WPA not working

[Giacomo Comes <comes@naic.edu>]

[-- Attachment #1: Type: text/plain, Size: 8040 bytes --]

On Wed, Nov 24, 2010 at 07:06:12PM +0000, Dave Kilroy wrote:
> On Mon, Nov 22, 2010 at 2:42 AM, Giacomo Comes <comes@naic.edu> wrote:
> > I'm having trouble with a wireless card using the orinoco driver.
> >
> > The card is (pccardctl ident output):
> >
> > Socket 2:
> >  product info: "Dell", "TrueMobile 1150 Series PC Card", "Version 01.01", ""
> >  manfid: 0x0156, 0x0002
> >  function: 6 (network)
> 
> This is the same card I used to develop the WPA functionality in orinoco.
> 
> > I'm running suse 11.3 with kernel 2.6.34.7
> 
> > [   14.498825] orinoco_cs 0.15 (David Gibson <hermes@gibson.dropbear.id.au>, Pavel Roskin <proski@gnu.org>, et al)
> > [   14.587767] orinoco_cs 2.0: Hardware identity 0005:0004:0005:0000
> > [   14.587897] orinoco_cs 2.0: Station identity  001f:0001:0008:000a
> > [   14.587906] orinoco_cs 2.0: Firmware determined as Lucent/Agere 8.10
> > [   14.587915] orinoco_cs 2.0: firmware: requesting agere_sta_fw.bin
> > [   14.698324] orinoco_cs 2.0: Hardware identity 0005:0004:0005:0000
> > [   14.698457] orinoco_cs 2.0: Station identity  001f:0002:0009:0030
> > [   14.698466] orinoco_cs 2.0: Firmware determined as Lucent/Agere 9.48
> > [   14.698472] orinoco_cs 2.0: Ad-hoc demo mode supported
> > [   14.698478] orinoco_cs 2.0: IEEE standard IBSS ad-hoc mode supported
> > [   14.698483] orinoco_cs 2.0: WEP supported, 104-bit key
> > [   14.698489] orinoco_cs 2.0: WPA-PSK supported
> 
> This means the driver should have been setup appropriately.
> 
> > [...]
> > [   32.967560] ADDRCONF(NETDEV_UP): eth1: link is not ready
> >
> >
> > NetworkManager is not able to connect to an AP and /var/log/messages contains:
> >
> > Nov 12 18:55:22 rescue kernel: [  388.982388] ------------[ cut here ]------------
> > Nov 12 18:55:22 rescue kernel: [  388.982427] WARNING: at /usr/src/packages/BUILD/kernel-desktop-2.6.34.7/linux-2.6.34/net/wireless/core.c:633 wdev_cleanup_work+0xb7/0xe0 [cfg80211]()
> > Nov 12 18:55:22 rescue kernel: [  388.982432] Hardware name: Latitude C840
> > Nov 12 18:55:22 rescue kernel: [  388.982435] Modules linked in: fuse ip6t_LOG xt_tcpudp xt_pkttype ipt_LOG xt_limit af_packet snd_pcm_oss snd_mixer_oss snd_seq snd_seq_device edd cpufreq_conservative cpufreq_userspace cpufreq_powersave speedstep_ich speedstep_lib mperf ip6t_REJECT nf_conntrack_ipv6 ip6table_raw xt_NOTRACK ipt_REJECT xt_state iptable_raw iptable_filter ip6table_mangle nf_conntrack_netbios_ns nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 ip_tables ip6table_filter ip6_tables x_tables loop dm_mod michael_mic orinoco_cs orinoco cfg80211 rfkill firewire_ohci firewire_core snd_intel8x0m pcmcia crc_itu_t snd_intel8x0 snd_ac97_codec ppdev ac97_bus iTCO_wdt sr_mod snd_pcm parport_pc ohci1394 yenta_socket rsrc_nonstatic dcdbas pcmcia_core ieee1394 3c59x video parport floppy snd_timer sg cdrom iTCO_vendor_support snd battery ac pcspkr joydev soundcore snd_page_alloc shpchp pci_hotplug ext4 jbd2 crc16 nouveau ttm drm_kms_helper drm i2c_algo_bit button intel_agp fan processor ata_generic thermal thermal_sys
> > Nov 12 18:55:22 rescue kernel: [  388.982543] Pid: 707, comm: cfg80211 Not tainted 2.6.34.7-0.5-desktop #1
> > Nov 12 18:55:22 rescue kernel: [  388.982546] Call Trace:
> > Nov 12 18:55:22 rescue kernel: [  388.982570]  [<c02065c3>] try_stack_unwind+0x173/0x190
> > Nov 12 18:55:22 rescue kernel: [  388.982580]  [<c02051cf>] dump_trace+0x3f/0xe0
> > Nov 12 18:55:22 rescue kernel: [  388.982589]  [<c020662b>] show_trace_log_lvl+0x4b/0x60
> > Nov 12 18:55:22 rescue kernel: [  388.982595]  [<c0206658>] show_trace+0x18/0x20
> > Nov 12 18:55:22 rescue kernel: [  388.982607]  [<c064e0b3>] dump_stack+0x6d/0x72
> > Nov 12 18:55:22 rescue kernel: [  388.982616]  [<c02443ae>] warn_slowpath_common+0x6e/0xb0
> > Nov 12 18:55:22 rescue kernel: [  388.982623]  [<c0244403>] warn_slowpath_null+0x13/0x20
> > Nov 12 18:55:22 rescue kernel: [  388.982635]  [<e2db5497>] wdev_cleanup_work+0xb7/0xe0 [cfg80211]
> > Nov 12 18:55:22 rescue kernel: [  388.982657]  [<c025cfa9>] run_workqueue+0x79/0x170
> > Nov 12 18:55:22 rescue kernel: [  388.982665]  [<c025d123>] worker_thread+0x83/0xe0
> > Nov 12 18:55:22 rescue kernel: [  388.982673]  [<c025fef4>] kthread+0x74/0x80
> > Nov 12 18:55:22 rescue kernel: [  388.982681]  [<c0203826>] kernel_thread_helper+0x6/0x10
> > Nov 12 18:55:22 rescue kernel: [  388.982688] ---[ end trace 3f0348b3b0c6f4ff ]---
> > Nov 12 18:55:25 rescue dhcpcd[6700]: eth1: dhcpcd not running
> 
> I've never seen this before. It looks like a scan is in progress when
> cfg80211 tries to do some cleanup - while bringing the interface down.

The patch you posted made this trace disappear.

> 
> > Nov 14 21:31:21 rescue ifup:     eth1      device: Dell
> > Nov 14 21:31:21 rescue ifup: TrueMobile 1150 Series PC Card
> > Nov 14 21:31:21 rescue ifup: Version 01.01
> > Nov 14 21:31:21 rescue ifup:     eth1      is controlled by ifplugd
> > Nov 14 21:31:21 rescue ifup:     eth1      device: Dell
> > Nov 14 21:31:21 rescue ifup: TrueMobile 1150 Series PC Card
> > Nov 14 21:31:21 rescue ifup: Version 01.01
> > Nov 14 21:31:21 rescue ifup-wireless:     eth1      warning: WPA configured, but is untested
> > Nov 14 21:31:21 rescue ifup-wireless:     eth1      warning: with this device
> > Nov 14 21:31:21 rescue ifup-wireless:     eth1      starting wpa_supplicant
> > Nov 14 21:31:21 rescue kernel: [   39.199513] ADDRCONF(NETDEV_UP): eth1: link is not ready
> > Nov 14 21:31:22 rescue ifup-dhcp: Starting DHCP4 client on eth1
> > Nov 14 21:31:22 rescue dhcpcd[3584]: eth1: dhcpcd 3.2.3 starting
> > Nov 14 21:31:22 rescue dhcpcd[3584]: eth1: hardware address = 00:02:2d:70:31:3b
> > Nov 14 21:31:22 rescue dhcpcd[3584]: eth1: broadcasting for a lease
> > Nov 14 21:31:22 rescue ifup-dhcp: .
> 
> <snip dhcp log> This isn't interesting. If wpa_supplicant hasn't
> connected you to an AP, dhcpcd isn't going to find anything.
> 
> > It first tryes to connect to an AP using WPA, but it fails.
> > Thereafter it connects to a second AP using WEP.
> 
> Can you provide wpa_supplicant logs? With a reasonable amount of
> debug. -dd should do.
> 

Attached you will find the wpa_supplicant.log created with the
following command line:
wpa_supplicant -ieth1 -c wpa_supplicant.conf -f wpa_supplicant.log -dd

> 
> > Another issue I have with the the orinoco_cs module is the following:
> > During suspend and resume there is a two minutes timeout period.
> 
> > More precisely, after I start to suspend the laptop the screen
> > goes black, the message
> >             s2disk: snapshotting the system
> > appears and then there is a two minutes period where the screen stays black
> > and nothing happens. After the two minutes, the messages snapshot ready
> > appears, the snapshot image is saved to the disk and the laptop turns off.
> > On resume, the kernel founds the snapshot image, loads it and then
> > stays two minutes doing nothing. After the two minutes, the text
> >                 s2disk: returned to userspace
> > appears on screen, there is some disk activity and then the sistem is back.
> >
> > If I blacklist the orinoco_cs module, then suspend and resume work properly.
> >
> > I have no idea if the two problems are related or not. If any of the issues
> > has been already discussed, please point me where I can find such discussion.
> 
> This is new. Depending on your kernel config, orinoco will either try
> to keep a copy of firmware which it re-flashes on resume, or try read
> the firmware on suspend, which is freed on resume. Both worked circa
> 2.6.32.
> 
> > If you need more informations or you want me to test some code let me know.
> 
> A wpa_supplicant log please. Note that the laptop I used to develop
> for (and on) has moved on, so there's only a limited number of things
> I can do to debug the issue.

If things don't go on, I will figure a way to give you access to the
truemobile card.

Regards.
Giacomo

[-- Attachment #2: wpa_supplicant.log --]
[-- Type: text/plain, Size: 4387 bytes --]

Initializing interface 'eth1' conf 'wpa_supplicant.conf' driver 'default' ctrl_interface 'N/A' bridge 'N/A'
Configuration file 'wpa_supplicant.conf' -> '/root/wpa_supplicant.conf'
Reading configuration file '/root/wpa_supplicant.conf'
ctrl_interface='/var/run/wpa_supplicant'
ctrl_interface_group='wheel'
Line: 3 - start of a new network block
ssid - hexdump_ascii(len=5):
     43 6f 6d 65 73                                    Comes           
PSK (ASCII passphrase) - hexdump_ascii(len=18): [REMOVED]
key_mgmt: 0x2
priority=5 (0x5)
proto: 0x1
PSK (from passphrase) - hexdump(len=32): [REMOVED]
Priority group 5
   id=0 ssid='Comes'
WEXT: cfg80211-based driver detected
SIOCGIWRANGE: WE(compiled)=22 WE(source)=21 enc_capa=0x5
  capabilities: key_mgmt 0x5 enc 0x7 flags 0x0
netlink: Operstate: linkmode=1, operstate=5
Own MAC address: 00:02:2d:70:31:3b
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=4 set_tx=0 seq_len=0 key_len=0
Driver did not support SIOCSIWENCODEEXT
wpa_driver_wext_set_key: alg=0 key_idx=5 set_tx=0 seq_len=0 key_len=0
Driver did not support SIOCSIWENCODEEXT
wpa_driver_wext_set_countermeasures
RSN: flushing PMKID list in the driver
Setting scan request: 0 sec 100000 usec
WPS: UUID based on MAC address - hexdump(len=16): 65 86 3e 36 18 13 57 3a b2 46 2f 88 c6 00 3e 7d
EAPOL: SUPP_PAE entering state DISCONNECTED
EAPOL: Supplicant port status: Unauthorized
EAPOL: KEY_RX entering state NO_KEY_RECEIVE
EAPOL: SUPP_BE entering state INITIALIZE
EAP: EAP entering state DISABLED
EAPOL: Supplicant port status: Unauthorized
EAPOL: Supplicant port status: Unauthorized
ctrl_interface_group=10 (from group name 'wheel')
Added interface eth1
RTM_NEWLINK: operstate=0 ifi_flags=0x1043 ([UP][RUNNING])
RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
RTM_NEWLINK: operstate=0 ifi_flags=0x1043 ([UP][RUNNING])
RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
Wireless event: cmd=0x8b06 len=8
RTM_NEWLINK: operstate=0 ifi_flags=0x1043 ([UP][RUNNING])
RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
Wireless event: cmd=0x8b1a len=8
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
State: DISCONNECTED -> SCANNING
Starting AP scan for wildcard SSID
Scan requested (ret=0) - scan timeout 5 seconds
EAPOL: disable timer tick
EAPOL: Supplicant port status: Unauthorized
Scan timeout - try to get results
Failed to get scan results
Failed to get scan results - try scanning again
Setting scan request: 1 sec 0 usec
Starting AP scan for wildcard SSID
Scan requested (ret=-1) - scan timeout 5 seconds
Failed to initiate AP scan.
Setting scan request: 1 sec 0 usec
Starting AP scan for wildcard SSID
Scan requested (ret=-1) - scan timeout 5 seconds
Failed to initiate AP scan.
Setting scan request: 1 sec 0 usec
Starting AP scan for wildcard SSID
Scan requested (ret=-1) - scan timeout 5 seconds
Failed to initiate AP scan.
Setting scan request: 1 sec 0 usec
Starting AP scan for wildcard SSID
Scan requested (ret=-1) - scan timeout 5 seconds
Failed to initiate AP scan.
Setting scan request: 1 sec 0 usec
Starting AP scan for wildcard SSID
Scan requested (ret=-1) - scan timeout 5 seconds
Failed to initiate AP scan.
Setting scan request: 1 sec 0 usec
Starting AP scan for wildcard SSID
Scan requested (ret=-1) - scan timeout 5 seconds
Failed to initiate AP scan.
Setting scan request: 1 sec 0 usec
Starting AP scan for wildcard SSID
Scan requested (ret=-1) - scan timeout 5 seconds
Failed to initiate AP scan.
Setting scan request: 1 sec 0 usec
CTRL-EVENT-TERMINATING - signal 2 received
Removing interface eth1
No keys have been configured - skip key clearing
State: SCANNING -> DISCONNECTED
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
netlink: Operstate: linkmode=-1, operstate=5
EAPOL: External notification - portEnabled=0
EAPOL: Supplicant port status: Unauthorized
EAPOL: External notification - portValid=0
EAPOL: Supplicant port status: Unauthorized
wpa_driver_wext_set_countermeasures
No keys have been configured - skip key clearing
Cancelling scan request
Cancelling authentication timeout
netlink: Operstate: linkmode=0, operstate=6