qca / open-ath9k-htc-firmware

The firmware for QCA AR7010/AR9271 802.11n USB NICs
Other
428 stars 182 forks source link

All kinds of weird problems when using more than one or two Atheros cards #114

Open rodizio1 opened 7 years ago

rodizio1 commented 7 years ago

I've beeen trying to narrow this issue down for months now, but it's so weird, really don't know what to do further. Already tried disabling LED blinking, but that didn't seem to help much.

Sometimes cards don't get initialized, sometimes they do, but don't receive packets, sometimes they do and receive packets only for a second or two then they crash.

[   62.491439] device ec086b1c7834 left promiscuous mode
[   62.495125] ath: phy3: Set HW RX filter: 0x37
[   62.506186] device ec086b1c4645 left promiscuous mode
[   62.514370] ath: phy2: Set HW RX filter: 0x37
[   62.521136] device c46e1f21bbf1 left promiscuous mode
[   62.535178] ath: phy1: Set HW RX filter: 0x37
[   63.355188] device c46e1f21bbf1 entered promiscuous mode
[   63.368003] ath: phy1: Set HW RX filter: 0x37
[   63.375141] device ec086b1c4645 entered promiscuous mode
[   63.389368] device ec086b1c7834 entered promiscuous mode
[   63.392006] ath: phy3: Set HW RX filter: 0x37
[   63.392372] ath: phy2: Set HW RX filter: 0x37
[   66.795152] cfg80211: Verifying active interfaces after reg change
[   86.338279] device ec086b1c7834 left promiscuous mode
[   86.344201] ath: phy3: Set HW RX filter: 0x37
[   86.358185] device ec086b1c4645 left promiscuous mode
[   86.370162] device c46e1f21bbf1 left promiscuous mode
[   86.377554] ath: phy2: Set HW RX filter: 0x37
[   86.378298] ath: phy1: Set HW RX filter: 0x37
[   87.191206] device c46e1f21bbf1 entered promiscuous mode
[   87.210421] ath: phy1: Set HW RX filter: 0x37
[   87.215230] device ec086b1c4645 entered promiscuous mode
[   87.218165] ath: phy2: Set HW RX filter: 0x37
[   87.233157] device ec086b1c7834 entered promiscuous mode
[   87.237414] ath: phy3: Set HW RX filter: 0x37
[   94.811654] device ec086b1c7834 left promiscuous mode
[   94.829155] device ec086b1c4645 left promiscuous mode
[   94.841140] device c46e1f21bbf1 left promiscuous mode
[   94.911149] ath: phy3: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   94.911174] ath: phy3: REGISTER READ FAILED: (0x803c, -110)
[   94.929142] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   94.929152] ath: phy2: REGISTER READ FAILED: (0x803c, -110)
[   94.941136] ath: phy1: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   94.941145] ath: phy1: REGISTER READ FAILED: (0x803c, -110)
[   95.011135] ath: phy3: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   95.011146] ath: phy3: REGISTER READ FAILED: (0x810c, -110)
[   95.029191] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   95.029201] ath: phy2: REGISTER READ FAILED: (0x810c, -110)
[   95.041133] ath: phy1: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   95.041141] ath: phy1: REGISTER READ FAILED: (0x810c, -110)
[   95.111132] ath: phy3: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   95.111152] ath: phy3: REGISTER RMW FAILED:(0x0034, -110)
[   95.129215] ath: phy2: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   95.129224] ath: phy2: REGISTER RMW FAILED:(0x0034, -110)
[   95.141139] ath: phy1: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   95.141148] ath: phy1: REGISTER RMW FAILED:(0x0034, -110)
[   95.211319] ath: phy3: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   95.211339] ath: phy3: REGISTER WRITE FAILED, multi len: 2
[   95.211351] ath: phy3: Set HW RX filter: 0x2137
[   95.229146] ath: phy2: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   95.229163] ath: phy2: REGISTER WRITE FAILED, multi len: 2
[   95.229172] ath: phy2: Set HW RX filter: 0x2137
[   95.241140] ath: phy1: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   95.241148] ath: phy1: REGISTER WRITE FAILED, multi len: 2
[   95.241157] ath: phy1: Set HW RX filter: 0x2137
[   95.699182] device c46e1f21bbf1 entered promiscuous mode
[   95.712196] device ec086b1c4645 entered promiscuous mode
[   95.728139] device ec086b1c7834 entered promiscuous mode
[   95.799152] ath: phy1: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   95.799175] ath: phy1: REGISTER READ FAILED: (0x803c, -110)
[   95.812125] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   95.812137] ath: phy2: REGISTER READ FAILED: (0x803c, -110)
[   95.828149] ath: phy3: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   95.828164] ath: phy3: REGISTER READ FAILED: (0x803c, -110)
[   95.899155] ath: phy1: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   95.899172] ath: phy1: REGISTER READ FAILED: (0x810c, -110)
[   95.912142] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   95.912159] ath: phy2: REGISTER READ FAILED: (0x810c, -110)
[   95.928154] ath: phy3: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   95.928172] ath: phy3: REGISTER READ FAILED: (0x810c, -110)
[   95.939883] device ec086b1c7834 left promiscuous mode
[   95.954228] device ec086b1c4645 left promiscuous mode
[   95.966261] device c46e1f21bbf1 left promiscuous mode
[   95.999147] ath: phy1: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   95.999165] ath: phy1: REGISTER RMW FAILED:(0x0034, -110)
[   96.012261] ath: phy2: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   96.012275] ath: phy2: REGISTER RMW FAILED:(0x0034, -110)
[   96.028299] ath: phy3: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   96.028349] ath: phy3: REGISTER RMW FAILED:(0x0034, -110)
[   96.099157] ath: phy1: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   96.099174] ath: phy1: REGISTER WRITE FAILED, multi len: 2
[   96.099181] ath: phy1: Set HW RX filter: 0x2137
[   96.112140] ath: phy2: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   96.112156] ath: phy2: REGISTER WRITE FAILED, multi len: 2
[   96.112165] ath: phy2: Set HW RX filter: 0x2137
[   96.128151] ath: phy3: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   96.128177] ath: phy3: REGISTER WRITE FAILED, multi len: 2
[   96.128185] ath: phy3: Set HW RX filter: 0x2137
[   96.199161] ath: phy1: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.199179] ath: phy1: REGISTER READ FAILED: (0x803c, -110)
[   96.212135] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.212146] ath: phy2: REGISTER READ FAILED: (0x803c, -110)
[   96.228147] ath: phy3: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.228161] ath: phy3: REGISTER READ FAILED: (0x803c, -110)
[   96.299148] ath: phy1: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.299168] ath: phy1: REGISTER READ FAILED: (0x810c, -110)
[   96.312145] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.312153] ath: phy2: REGISTER READ FAILED: (0x810c, -110)
[   96.328130] ath: phy3: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.328138] ath: phy3: REGISTER READ FAILED: (0x810c, -110)
[   96.399132] ath: phy1: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   96.399143] ath: phy1: REGISTER RMW FAILED:(0x0034, -110)
[   96.412147] ath: phy2: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   96.412155] ath: phy2: REGISTER RMW FAILED:(0x0034, -110)
[   96.428138] ath: phy3: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   96.428158] ath: phy3: REGISTER RMW FAILED:(0x0034, -110)
[   96.499135] ath: phy1: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   96.499147] ath: phy1: REGISTER WRITE FAILED, multi len: 2
[   96.499156] ath: phy1: Set HW RX filter: 0x2137
[   96.512162] ath: phy2: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   96.512170] ath: phy2: REGISTER WRITE FAILED, multi len: 2
[   96.512177] ath: phy2: Set HW RX filter: 0x2137
[   96.528283] ath: phy3: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   96.528322] ath: phy3: REGISTER WRITE FAILED, multi len: 2
[   96.528330] ath: phy3: Set HW RX filter: 0x2137
[   96.777224] device c46e1f21bbf1 entered promiscuous mode
[   96.791159] device ec086b1c4645 entered promiscuous mode
[   96.807129] device ec086b1c7834 entered promiscuous mode
[   96.877172] ath: phy1: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.877213] ath: phy1: REGISTER READ FAILED: (0x803c, -110)
[   96.891132] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.891141] ath: phy2: REGISTER READ FAILED: (0x803c, -110)
[   96.907130] ath: phy3: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.907139] ath: phy3: REGISTER READ FAILED: (0x803c, -110)
[   96.977128] ath: phy1: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.977137] ath: phy1: REGISTER READ FAILED: (0x810c, -110)
[   96.991127] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   96.991135] ath: phy2: REGISTER READ FAILED: (0x810c, -110)
[   97.007124] ath: phy3: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   97.007133] ath: phy3: REGISTER READ FAILED: (0x810c, -110)
[   97.077130] ath: phy1: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   97.077140] ath: phy1: REGISTER RMW FAILED:(0x0034, -110)
[   97.091162] ath: phy2: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   97.091185] ath: phy2: REGISTER RMW FAILED:(0x0034, -110)
[   97.107124] ath: phy3: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   97.107140] ath: phy3: REGISTER RMW FAILED:(0x0034, -110)
[   97.177140] ath: phy1: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   97.177155] ath: phy1: REGISTER WRITE FAILED, multi len: 2
[   97.177166] ath: phy1: Set HW RX filter: 0x2137
[   97.191130] ath: phy2: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   97.191139] ath: phy2: REGISTER WRITE FAILED, multi len: 2
[   97.191146] ath: phy2: Set HW RX filter: 0x2137
[   97.207131] ath: phy3: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   97.207139] ath: phy3: REGISTER WRITE FAILED, multi len: 2
[   97.207146] ath: phy3: Set HW RX filter: 0x2137

When this occurs, packet reception stops, ifconfig RX bytes/packets does not increase anymore.

Tried to unload the ath9k module, this seems to have crashed the whole USB subsystem, my ssh connection is gone and keyboard also doesn't work anymore.

It doesn't occur always and sometimes the REGISTER READ FAILED message don't seem to cause issues, here it looks like two of the three cards don't work:

[   12.637170] device c46e1f21bbf1 entered promiscuous mode
[   12.737172] ath: phy1: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   12.737189] ath: phy1: REGISTER READ FAILED: (0x803c, -110)
[   12.837174] ath: phy1: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   12.837191] ath: phy1: REGISTER READ FAILED: (0x810c, -110)
[   12.937164] ath: phy1: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   12.937174] ath: phy1: REGISTER RMW FAILED:(0x0034, -110)
[   13.037171] ath: phy1: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   13.037187] ath: phy1: REGISTER WRITE FAILED, multi len: 2
[   13.037195] ath: phy1: Set HW RX filter: 0x2137
[   13.649167] device ec086b1c4645 entered promiscuous mode
[   13.749169] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   13.749184] ath: phy2: REGISTER READ FAILED: (0x803c, -110)
[   13.849174] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   13.849189] ath: phy2: REGISTER READ FAILED: (0x810c, -110)
[   13.949169] ath: phy2: Timeout waiting for WMI command: WMI_REG_RMW_CMDID
[   13.949183] ath: phy2: REGISTER RMW FAILED:(0x0034, -110)
[   14.049172] ath: phy2: Timeout waiting for WMI command: WMI_REG_WRITE_CMDID
[   14.049188] ath: phy2: REGISTER WRITE FAILED, multi len: 2
[   14.049195] ath: phy2: Set HW RX filter: 0x2137
[   14.661168] device ec086b1c7834 entered promiscuous mode
[   14.665794] ath: phy3: Set HW RX filter: 0x37

But actually, only the first card doesn't work (5.3MiB received vs. 200MiB received):

c46e1f21bbf1 Link encap:UNSPEC  HWaddr C4-6E-1F-21-BB-F1-28-01-00-00-00-00-00-00-00-00
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:5132 errors:0 dropped:4528 overruns:0 frame:0
          TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:5604144 (5.3 MiB)  TX bytes:0 (0.0 B)

ec086b1c4645 Link encap:UNSPEC  HWaddr EC-08-6B-1C-46-45-00-00-00-00-00-00-00-00-00-00
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:195558 errors:0 dropped:4218 overruns:0 frame:0
          TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:213549336 (203.6 MiB)  TX bytes:0 (0.0 B)

ec086b1c7834 Link encap:UNSPEC  HWaddr EC-08-6B-1C-78-34-00-00-00-00-00-00-00-00-00-00
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:193286 errors:0 dropped:3218 overruns:0 frame:0
          TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:211068312 (201.2 MiB)  TX bytes:0 (0.0 B)

Next test I wanted to do was to check if setting the cards in promiscous mode has something to do with it, rebooted and tried:

iwconfig wlan0 mode monitor ifconfig wlan0 up

Now the USB subsystem seems frozen again.

Next try was to only disable the packet reception in my startup script. Rebooted, now I cannot get three cards to work anymore at all. It always hangs while initializing the cards (bringing them up and into monitor mode on the desired channel).

The weird thing is, nothing regarding the wifi cards was changed, just commented out a line in a script that runs way after the initialization of the wifi cards. I know this sounds not logic at all, but I've had such weird behaviour on different occasions. It seems that just changing something completely unrelated makes a difference. Not sure why, maybe because some stuff gets loaded or executed with a few nano or milli-seconds different when files have changed on the sdcard?

Users of my EZ-Wifibroadcast image also reported similar things, some had problems with a newer version although they did not change anything with their hardware or setup and I did just some scripting cleanups and cosmetic stuff, i.e. nothing that would affect the wifi cards at all.

One user reported he could trigger that behaviour just by choosing a different channel, which also seems to make no sense at all.

I also could find forum posts from users trying to use more than two Atheros sticks from more than a year ago, they suffered the same problems.

Next test again with two cards. This time I can succesfully bring them up and issue "ifconfig wlan0 promisc".

Now the weird thing is, when I set the cards to promiscous mode via ifconfig, it seems to always trigger that REGISTER_READ_TIMEOUT message. However, sometimes the card is still able to receive packets, even though the message appeared. After running "ifconfig wlan0 promisc" a few times in a row though, it certainly stops working.

I can also trigger this with only one card. I.e. start-up the system, configure card, run "ifconfig promisc" for maybe 5-10 times and the card crashes.

Some general infos:

olerem commented 7 years ago

All REG related commands go over EP3 and EP4. This EPs was configured for some time as Bulk, then i added patches to revert this behavior back to Interrupt mode. Latest kernel and FW should include some optimization for this EPs. Which kernel version and FW versions are you using, do this changes applied or not? I can imagine different usb related issues:

I assume, it should be possible to reduce this problems by mowing as match functionality as possible to the FW. So we avoid direct REG read/write operations.

Currently without FW changes, you can reduce EP3/EP4 load by disabling LED and bgscan, if this are enabled.

rodizio1 commented 7 years ago

Kernel is 4.4.11, ath9k_htc-firmware is version 1.4.

LED blink is already disabled. It is definitely not a power or cable issue (see my initial post).

How do I disable bgscan? Couldn't find anything about it with a quick search. Or do you mean scans that get initiated by network-manager or wpa-supplicant etc.?

Network-manager, wpa-supplicant and everything else that might mess with the cards is disabled. Only thing I do is bring up the interface, set monitor mode and channel (all via plain ifconfig/iwconfig) then I start the rx program that puts the cards into promiscous mode.

Regarding not enough USB bandwidth: Well, I have never really measured USB bandwidth on the Pi, but it works flawless with four Ralink cards. So far I didn't notice it being slow when copying files over the USB ethernet connection or to an USB memory stick.

The incoming data is something around 500 1024bytes packets per second per dongle, so not too much.

Regarding the packet size: I read somewhere, that USB max. packet size is 512bytes for bulk transfer. So assuming some overhead, I figured 1024 bytes ethernet packets will probably lead to 2x 512 bytes packets plus 1x 20bytes (or whatever low number) packets on the USB Bus, i.e. something similar to fragmentation in the IP world that is best to be avoided. But lowering the packet size to 900 didn't seem to make a difference.

olerem commented 7 years ago

hm.. so, what do i need to reproduce this issue?

rodizio1 commented 7 years ago

I just downloaded the latest Raspbian lite image to have a fresh clean install. Could not reproduce the issue with putting the cards in promiscous mode when I gave it a quick try.

However, as soon as I plug in the 3rd AR9271 stick, my USB keyboard does strange things (like repeating characters that I did not press and being laggy) and stops working completely shortly after.

When starting the Pi3 with the three sticks already attached, the keyboard keeps working, but I end up with only one card being shown with iwconfig.

Not sure if that is something easy for you to reproduce. If I can do something to narrow it down some more I'll gladly do that.

rodizio1 commented 7 years ago

Did some more testing. One issue really seems to be switching the cards to promiscous mode.

I have now changed this line in the code of the rx program that receives the packets: interface->ppcap = pcap_open_live(name, 2048, **1**, -1, szErrbuf);

to this: interface->ppcap = pcap_open_live(name, 2048, **0**, -1, szErrbuf);

to disable putting the cards into promiscous mode, and the problem that the cards stop receiving traffic shortly after the rx program has been started sometimes is gone.

But the problem that cards don't get initialized if more than two or three cards are used is still there. I'll compile a kernel with wireless and atheros debugging enabled on the fresh Raspbian image now and check further ...

olerem commented 7 years ago

In promiscous mode the card will dump everything what it get from the air over usb. It means, depending on environment you will get different results. Some project already filed becouse of this :) Do you get same 2-3 card issue on simple Linux PC too?

rodizio1 commented 7 years ago

The rx program still works as intended with promisc mode disabled, I guess this is because wireless cards in monitor mode forward all traffic anyway (?) As far as I see it in the code, it sets a pcap filter and uses a special mac address to filter traffic:

"radio[0x4a:4]==0x13223344 && radio[0x4e:2] == 0x55%.2x", port); Too much (other) traffic is not the problem, this also happens with antennas off or on channel 14.

I will try to see what happens on a linux notebook.

BTW (little offtopic): To optimize that further, would it in theory be possible to filter out traffic based on mac addresses already in the atheros firmware, so that it doesn't even reach the host? And basically don't listen to other packets at all, i.e. abort reception and listen again as soon as the header with macs has been read?

olerem commented 7 years ago

s/promiscous/monitore you are right... where are my thoughts

IMO filtering in the firmware should be good point. @erikarn , what do you think? I think this should help some other users too.

rodizio1 commented 7 years ago

Compiled a kernel now with ath9k_htc debugging enabled on the fresh Raspbian lite image. Kernel has stock Raspbian config (just some un-needed unrelated drivers removed to speed up compilation on the Pi) and is the same version as the stock Raspbian one.

two sticks already plugged before power-on, then plugged the third stick:

[   71.512684] usb 1-1.2: new high-speed USB device number 7 using dwc_otg
[   71.633826] usb 1-1.2: New USB device found, idVendor=0cf3, idProduct=9271
[   71.633846] usb 1-1.2: New USB device strings: Mfr=16, Product=32, SerialNumber=48
[   71.633859] usb 1-1.2: Product: UB91C
[   71.633872] usb 1-1.2: Manufacturer: ATHEROS
[   71.633884] usb 1-1.2: SerialNumber: 12345
[   71.635278] usb 1-1.2: ath9k_htc: Firmware ath9k_htc/htc_9271-1.4.0.fw requested
[   71.933879] usb 1-1.2: ath9k_htc: Transferred FW: ath9k_htc/htc_9271-1.4.0.fw, size: 51008
[   73.420618] ath9k_htc 1-1.2:1.0: ath9k_htc: HTC initialized with 33 credits
[   73.598751] ath: phy2: serialize_regmode is 0
[   73.598888] ath: phy2: UNDEFINED -> AWAKE
[   73.610212] ath: phy2: Reading from EEPROM, not flash
[   74.712633] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   74.712648] ath: phy2: Multiple REGISTER READ FAILED (count: 8)
[   75.712640] ath: phy2: Timeout waiting for WMI command: WMI_REG_READ_CMDID
[   75.712667] ath: phy2: Multiple REGISTER READ FAILED (count: 8)
[   77.671673] ath: phy2: Read Magic = 0xA55A
[   77.671693] ath: phy2: need_swap = False
[   77.671708] ath: phy2: Bad EEPROM checksum 0xd382 or revision 0x000e
[   77.671753] ath: phy2: Unable to initialize hardware; initialization status: -22
[   77.671764] ath: phy2: Unable to initialize hardware; initialization status: -22
[   77.671802] ath9k_htc: Failed to initialize the device
[   77.673514] usb 1-1.2: ath9k_htc: USB layer deinitialized

After some tries, three sticks connected before power-up worked, but when plugging the 4th one:

[   87.633090] usb 1-1.5.1: new high-speed USB device number 8 using dwc_otg
[   87.884476] usb 1-1.5.1: New USB device found, idVendor=0cf3, idProduct=9271
[   87.884499] usb 1-1.5.1: New USB device strings: Mfr=16, Product=32, SerialNumber=48
[   87.884512] usb 1-1.5.1: Product: USB2.0 WLAN
[   87.884525] usb 1-1.5.1: Manufacturer: ATHEROS
[   87.884569] usb 1-1.5.1: SerialNumber: 12345
[   87.886007] usb 1-1.5.1: ath9k_htc: Firmware ath9k_htc/htc_9271-1.4.0.fw requested
[   88.186557] usb 1-1.5.1: ath9k_htc: Transferred FW: ath9k_htc/htc_9271-1.4.0.fw, size: 51008
[   89.803089] usb 1-1.5.1: Service connection timeout for: 258
[   89.803104] ath9k_htc 1-1.5.1:1.0: ath9k_htc: Unable to initialize HTC services
[   89.803129] ath9k_htc: Failed to initialize the device
[   89.803970] usb 1-1.5.1: ath9k_htc: USB layer deinitialized

In both cases "modprobe -r ath9k_htc" made atleast the USB subsystem crash (ssh connection and usb keyboard didn't work anymore). I'll see that I configure the serialport to see what is going on then.

erikarn commented 7 years ago

That's weird, seeing transfer timeouts is a big problem. Can you enable some debugging or capture the USB traffic on that USB port?

-a

rodizio1 commented 7 years ago

The dmesg log above was with ath9k_htc module parameter debug=0xffffffff, can I enable more debugging somewhere?

Here is a .pcap made with the usbmon module while plugging in a third card (two were already connected during boot-up). usbcapture.zip

The corresponding dmesg output: [ 61.382340] usb 1-1.4: new high-speed USB device number 6 using dwc_otg [ 61.487370] usb 1-1.4: New USB device found, idVendor=0cf3, idProduct=9271 [ 61.487398] usb 1-1.4: New USB device strings: Mfr=16, Product=32, SerialNumber=48 [ 61.487407] usb 1-1.4: Product: USB2.0 WLAN [ 61.487414] usb 1-1.4: Manufacturer: ATHEROS [ 61.487422] usb 1-1.4: SerialNumber: 12345 [ 62.489355] usb 1-1.4: ath9k_htc: Firmware ath9k_htc/htc_9271-1.18.0.fw requested [ 62.781667] usb 1-1.4: ath9k_htc: Transferred FW: ath9k_htc/htc_9271-1.18.0.fw, size: 51008 [ 66.283344] cfg80211: Verifying active interfaces after reg change [ 68.297143] ath9k_htc 1-1.4:1.0: ath9k_htc: HTC initialized with 33 credits [ 68.396340] ath: phy3: Timeout waiting for WMI command: WMI_REG_READ_CMDID [ 68.396349] ath: phy3: REGISTER READ FAILED: (0x4020, -110) [ 68.396357] ath: phy3: Mac Chip Rev 0x0f.3 is not supported by this driver [ 68.396364] ath: phy3: Unable to initialize hardware; initialization status: -95 [ 68.396371] ath: phy3: Unable to initialize hardware; initialization status: -95 [ 68.396401] ath9k_htc: Failed to initialize the device [ 68.397502] usb 1-1.4: ath9k_htc: USB layer deinitialized

Please note, this was not made on the fresh Raspbian image, but on my EZ-Wifibroadcast image which has a different kernel with 1000Hz timer frequency.Not sure if that makes a difference, I can do it again with the other clean Raspbian image with stock kernel if needed. If you are wondering about the strange firmware version, it's a 1.4 firmware, only change is it has an 18mbit fixed bitrate, I made different firmware files for different fixed bitrates.

olerem commented 7 years ago

can you recompile the kernel with this change? diff --git a/drivers/net/wireless/ath/ath9k/hif_usb.h b/drivers/net/wireless/ath/ath9k/hif_usb.h index 7c2ef7e..438701c 100644 --- a/drivers/net/wireless/ath/ath9k/hif_usb.h +++ b/drivers/net/wireless/ath/ath9k/hif_usb.h @@ -61,7 +61,7 @@ extern int htc_use_dev_fw;

define MAX_PKT_NUM_IN_TRANSFER 10

define MAX_REG_OUT_URB_NUM 1

-#define MAX_REG_IN_URB_NUM 64 +#define MAX_REG_IN_URB_NUM 8

define MAX_REG_IN_BUF_SIZE 64

rodizio1 commented 7 years ago

Tried the patch on the stock raspbian 4.4.32 kernel on the clean image now, I think it makes no difference.

This is a complete dmesg log from bootup with four adapters installed. Will do more testing ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 4.4.32-v7 (root@raspberrypi) (gcc version 4.9.2 (Raspbian 4.9.2-10) ) #1 SMP Mon Nov 21 21:53:32 UTC 2016
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] Machine model: Raspberry Pi 3 Model B Rev 1.2
[    0.000000] cma: Reserved 8 MiB at 0x3a800000
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] On node 0 totalpages: 241664
[    0.000000] free_area_init_node: node 0, pgdat 807b31c0, node_mem_map b9fa6000
[    0.000000]   Normal zone: 2124 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 241664 pages, LIFO batch:31
[    0.000000] [bcm2709_smp_init_cpus] enter (9520->f3003010)
[    0.000000] [bcm2709_smp_init_cpus] ncores=4
[    0.000000] PERCPU: Embedded 13 pages/cpu @b9f62000 s22592 r8192 d22464 u53248
[    0.000000] pcpu-alloc: s22592 r8192 d22464 u53248 alloc=13*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 239540
[    0.000000] Kernel command line: 8250.nr_uarts=1 dma.dmachans=0x7f35 bcm2708_fb.fbwidth=1920 bcm2708_fb.fbheight=1200 bcm2709.boardrev=0x2a02082 bcm2709.serial=0xadfc03e7 smsc95xx.macaddr=B8:27:EB:FC:03:E7 bcm2708_fb.fbswap=1 bcm2709.uart_clock=48000000 vc_mem.mem_base=0x3dc00000 vc_mem.mem_size=0x3f000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 940188K/966656K available (5599K kernel code, 303K rwdata, 1544K rodata, 428K init, 749K bss, 18276K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xbb800000 - 0xff800000   (1088 MB)
    lowmem  : 0x80000000 - 0xbb000000   ( 944 MB)
    modules : 0x7f000000 - 0x80000000   (  16 MB)
      .text : 0x80008000 - 0x80702008   (7145 kB)
      .init : 0x80703000 - 0x8076e000   ( 428 kB)
      .data : 0x8076e000 - 0x807b9cb0   ( 304 kB)
       .bss : 0x807bc000 - 0x80877628   ( 750 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000]  Build-time adjustment of leaf fanout to 32.
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] Architected cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000010] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000027] Switching to timer-based delay loop, resolution 52ns
[    0.000295] Console: colour dummy device 80x30
[    0.001340] console [tty1] enabled
[    0.001393] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.001460] pid_max: default: 32768 minimum: 301
[    0.001793] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001836] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.002791] Disabling cpuset control group subsystem
[    0.002847] Initializing cgroup subsys io
[    0.002898] Initializing cgroup subsys memory
[    0.002962] Initializing cgroup subsys devices
[    0.003004] Initializing cgroup subsys freezer
[    0.003045] Initializing cgroup subsys net_cls
[    0.003116] CPU: Testing write buffer coherency: ok
[    0.003201] ftrace: allocating 18658 entries in 55 pages
[    0.046618] CPU0: update cpu_capacity 1024
[    0.046683] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.046716] [bcm2709_smp_prepare_cpus] enter
[    0.046870] Setting up static identity map for 0x8240 - 0x8274
[    0.048541] [bcm2709_boot_secondary] cpu:1 started (0) 17
[    0.048868] [bcm2709_secondary_init] enter cpu:1
[    0.048910] CPU1: update cpu_capacity 1024
[    0.048916] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.049290] [bcm2709_boot_secondary] cpu:2 started (0) 17
[    0.049550] [bcm2709_secondary_init] enter cpu:2
[    0.049571] CPU2: update cpu_capacity 1024
[    0.049577] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.049934] [bcm2709_boot_secondary] cpu:3 started (0) 16
[    0.050115] [bcm2709_secondary_init] enter cpu:3
[    0.050136] CPU3: update cpu_capacity 1024
[    0.050142] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.050202] Brought up 4 CPUs
[    0.050301] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.050331] CPU: All CPU(s) started in HYP mode.
[    0.050357] CPU: Virtualization extensions available.
[    0.050990] devtmpfs: initialized
[    0.061795] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.062171] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.062902] pinctrl core: initialized pinctrl subsystem
[    0.063386] NET: Registered protocol family 16
[    0.068504] DMA: preallocated 4096 KiB pool for atomic coherent allocations
[    0.075484] bcm2709: Mini UART enabled
[    0.075543] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.075590] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.075756] Serial: AMBA PL011 UART driver
[    0.075910] uart-pl011 3f201000.uart: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[    0.076145] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.138765] bcm2835-dma 3f007000.dma: DMA legacy API manager at f3007000, dmachans=0x1
[    0.139352] SCSI subsystem initialized
[    0.139555] usbcore: registered new interface driver usbfs
[    0.139666] usbcore: registered new interface driver hub
[    0.139784] usbcore: registered new device driver usb
[    0.146187] raspberrypi-firmware soc:firmware: Attached to firmware from 2016-11-16 12:24
[    0.173271] clocksource: Switched to clocksource arch_sys_counter
[    0.192678] FS-Cache: Loaded
[    0.192984] CacheFiles: Loaded
[    0.205309] NET: Registered protocol family 2
[    0.206160] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.206296] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.206507] TCP: Hash tables configured (established 8192 bind 8192)
[    0.206622] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.206689] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.206947] NET: Registered protocol family 1
[    0.207927] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    0.209304] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.222388] VFS: Disk quotas dquot_6.6.0
[    0.222712] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.226679] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[    0.226855] io scheduler noop registered
[    0.226895] io scheduler deadline registered (default)
[    0.226969] io scheduler cfq registered
[    0.229446] BCM2708FB: allocated DMA memory fac10000
[    0.229493] BCM2708FB: allocated DMA channel 0 @ f3007000
[    0.293872] Console: switching to colour frame buffer device 240x75
[    0.332208] Serial: 8250/16550 driver, 1 ports, IRQ sharing disabled
[    0.333431] console [ttyS0] disabled
[    0.333603] 3f215040.uart: ttyS0 at MMIO 0x3f215040 (irq = 59, base_baud = 31250000) is a 16550
[    1.021249] console [ttyS0] enabled
[    1.805253] bcm2835-rng 3f104000.rng: hwrng registered
[    1.810784] vc-cma: Videocore CMA driver
[    1.814909] vc-cma: vc_cma_base      = 0x00000000
[    1.819813] vc-cma: vc_cma_size      = 0x00000000 (0 MiB)
[    1.825463] vc-cma: vc_cma_initial   = 0x00000000 (0 MiB)
[    1.831364] vc-mem: phys_addr:0x00000000 mem_base=0x3dc00000 mem_size:0x3f000000(1008 MiB)
[    1.855029] brd: module loaded
[    1.867042] loop: module loaded
[    1.871306] vchiq: vchiq_init_state: slot_zero = 0xbac80000, is_master = 0
[    1.880163] Loading iSCSI transport class v2.0-870.
[    1.885940] usbcore: registered new interface driver smsc95xx
[    1.891976] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    2.098266] Core Release: 2.80a
[    2.101548] Setting default values for core params
[    2.106589] Finished setting default values for core params
[    2.312760] Using Buffer DMA mode
[    2.316232] Periodic Transfer Interrupt Enhancement - disabled
[    2.322307] Multiprocessor Interrupt Enhancement - disabled
[    2.328137] OTG VER PARAM: 0, OTG VER FLAG: 0
[    2.332683] Dedicated Tx FIFOs mode
[    2.336651] WARN::dwc_otg_hcd_init:1047: FIQ DMA bounce buffers: virt = 0xbac04000 dma = 0xfac04000 len=9024
[    2.346927] FIQ FSM acceleration enabled for :
Non-periodic Split Transactions
Periodic Split Transactions
High-Speed Isochronous Endpoints
Interrupt/Control Split Transaction hack enabled
[    2.370204] dwc_otg: Microframe scheduler enabled
[    2.370254] WARN::hcd_init_fiq:413: FIQ on core 1 at 0x803cded4
[    2.376419] WARN::hcd_init_fiq:414: FIQ ASM at 0x803ce244 length 36
[    2.382951] WARN::hcd_init_fiq:439: MPHI regs_base at 0xbb87e000
[    2.389283] dwc_otg 3f980000.usb: DWC OTG Controller
[    2.394501] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    2.402144] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[    2.408009] Init: Port Power? op_state=1
[    2.412097] Init: Power Port (0)
[    2.415674] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    2.422752] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.439139] usb usb1: Product: DWC OTG Controller
[    2.452901] usb usb1: Manufacturer: Linux 4.4.32-v7 dwc_otg_hcd
[    2.467914] usb usb1: SerialNumber: 3f980000.usb
[    2.482437] hub 1-0:1.0: USB hub found
[    2.495333] hub 1-0:1.0: 1 port detected
[    2.508872] dwc_otg: FIQ enabled
[    2.508881] dwc_otg: NAK holdoff enabled
[    2.508889] dwc_otg: FIQ split-transaction FSM enabled
[    2.508923] Module dwc_common_port init
[    2.509212] usbcore: registered new interface driver usb-storage
[    2.524578] mousedev: PS/2 mouse device common for all mice
[    2.539944] bcm2835-cpufreq: min=600000 max=1200000
[    2.554092] sdhci: Secure Digital Host Controller Interface driver
[    2.569389] sdhci: Copyright(c) Pierre Ossman
[    2.583130] sdhost: log_buf @ bac07000 (fac07000)
[    2.653300] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    2.670133] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[    2.685010] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[    2.710373] mmc0: host does not support reading read-only switch, assuming write-enable
[    2.713401] Indeed it is in host mode hprt0 = 00021501
[    2.743792] mmc0: new high speed SDHC card at address 59b4
[    2.758941] mmcblk0: mmc0:59b4 USDU1 30.0 GiB
[    2.773468] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.788671] ledtrig-cpu: registered to indicate activity on CPUs
[    2.788797]  mmcblk0: p1 p2
[    2.808087] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    2.809649] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.811218] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.814083] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    2.872166] hidraw: raw HID events driver (C) Jiri Kosina
[    2.886442] usbcore: registered new interface driver usbhid
[    2.893309] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    2.893448] Indeed it is in host mode hprt0 = 00001101
[    2.904746] mmc1: new high speed SDIO card at address 0001
[    2.943899] usbhid: USB HID core driver
[    2.956973] Initializing XFRM netlink socket
[    2.969826] NET: Registered protocol family 17
[    2.982796] Key type dns_resolver registered
[    2.995903] Registering SWP/SWPB emulation handler
[    3.009939] registered taskstats version 1
[    3.022651] vc-sm: Videocore shared memory driver
[    3.035884] [vc_sm_connected_init]: start
[    3.048946] [vc_sm_connected_init]: end - returning 0
[    3.063994] 3f201000.uart: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[    3.081745] of_cfs_init
[    3.083625] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    3.083634] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.084370] hub 1-1:1.0: USB hub found
[    3.084470] hub 1-1:1.0: 5 ports detected
[    3.148639] of_cfs_init: OK
[    3.197204] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    3.214066] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    3.237873] devtmpfs: mounted
[    3.250078] Freeing unused kernel memory: 428K (80703000 - 8076e000)
[    3.363318] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    3.493674] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    3.509687] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.528969] smsc95xx v1.0.4
[    3.596907] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:fc:03:e7
[    3.600170] random: systemd: uninitialized urandom read (16 bytes read, 68 bits of entropy available)
[    3.639852] systemd[1]: systemd 215 running in system mode. (+PAM +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ -SECCOMP -APPARMOR)
[    3.663090] systemd[1]: Detected architecture 'arm'.
[    3.811379] NET: Registered protocol family 10
[    3.826865] systemd[1]: Inserted module 'ipv6'
[    3.842610] systemd[1]: Set hostname to <raspberrypi>.
[    3.883325] usb 1-1.2: new high-speed USB device number 4 using dwc_otg
[    4.021676] random: systemd-sysv-ge: uninitialized urandom read (16 bytes read, 70 bits of entropy available)
[    4.042116] usb 1-1.2: New USB device found, idVendor=0cf3, idProduct=9271
[    4.058849] usb 1-1.2: New USB device strings: Mfr=16, Product=32, SerialNumber=48
[    4.076258] usb 1-1.2: Product: USB2.0 WLAN
[    4.090544] usb 1-1.2: Manufacturer: ATHEROS
[    4.104550] usb 1-1.2: SerialNumber: 12345
[    4.150909] random: systemd: uninitialized urandom read (16 bytes read, 72 bits of entropy available)
[    4.171224] random: systemd: uninitialized urandom read (16 bytes read, 72 bits of entropy available)
[    4.191462] random: systemd: uninitialized urandom read (16 bytes read, 72 bits of entropy available)
[    4.226459] random: systemd: uninitialized urandom read (16 bytes read, 73 bits of entropy available)
[    4.246099] random: systemd: uninitialized urandom read (16 bytes read, 73 bits of entropy available)
[    4.264823] random: systemd: uninitialized urandom read (16 bytes read, 73 bits of entropy available)
[    4.319794] random: systemd: uninitialized urandom read (16 bytes read, 73 bits of entropy available)
[    4.344964] random: systemd: uninitialized urandom read (16 bytes read, 73 bits of entropy available)
[    4.363321] usb 1-1.3: new high-speed USB device number 5 using dwc_otg
[    4.459592] systemd[1]: Cannot add dependency job for unit display-manager.service, ignoring: Unit display-manager.service failed to load: No such file or directory.
[    4.487359] systemd[1]: Expecting device dev-ttyS0.device...
[    4.513248] systemd[1]: Starting Forward Password Requests to Wall Directory Watch.
[    4.530978] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    4.548176] usb 1-1.3: New USB device found, idVendor=0cf3, idProduct=9271
[    4.548193] systemd[1]: Starting Remote File Systems (Pre).
[    4.579763] usb 1-1.3: New USB device strings: Mfr=16, Product=32, SerialNumber=48
[    4.579771] usb 1-1.3: Product: UB91C
[    4.579781] usb 1-1.3: Manufacturer: ATHEROS
[    4.579788] usb 1-1.3: SerialNumber: 12345
[    4.647940] systemd[1]: Reached target Remote File Systems (Pre).
[    4.663787] systemd[1]: Starting Network is Online.
[    4.689065] systemd[1]: Reached target Network is Online.
[    4.704420] systemd[1]: Starting Arbitrary Executable File Formats File System Automount Point.
[    4.734476] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    4.754198] systemd[1]: Starting Encrypted Volumes.
[    4.780072] systemd[1]: Reached target Encrypted Volumes.
[    4.795842] systemd[1]: Starting Swap.
[    4.820696] systemd[1]: Reached target Swap.
[    4.835150] systemd[1]: Expecting device dev-mmcblk0p1.device...
[    4.862351] systemd[1]: Starting Root Slice.
[    4.873304] usb 1-1.4: new high-speed USB device number 6 using dwc_otg
[    4.904887] systemd[1]: Created slice Root Slice.
[    4.919822] systemd[1]: Starting User and Session Slice.
[    4.946434] systemd[1]: Created slice User and Session Slice.
[    4.962448] systemd[1]: Starting /dev/initctl Compatibility Named Pipe.
[    4.990695] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    5.008122] systemd[1]: Starting Delayed Shutdown Socket.
[    5.024184] usb 1-1.4: New USB device found, idVendor=0cf3, idProduct=9271
[    5.024197] usb 1-1.4: New USB device strings: Mfr=16, Product=32, SerialNumber=48
[    5.024204] usb 1-1.4: Product: USB2.0 WLAN
[    5.024213] usb 1-1.4: Manufacturer: ATHEROS
[    5.024219] usb 1-1.4: SerialNumber: 12345
[    5.113391] systemd[1]: Listening on Delayed Shutdown Socket.
[    5.129100] systemd[1]: Starting Journal Socket (/dev/log).
[    5.155084] systemd[1]: Listening on Journal Socket (/dev/log).
[    5.170681] systemd[1]: Starting udev Control Socket.
[    5.195951] systemd[1]: Listening on udev Control Socket.
[    5.211068] systemd[1]: Starting udev Kernel Socket.
[    5.236325] systemd[1]: Listening on udev Kernel Socket.
[    5.251360] systemd[1]: Starting Journal Socket.
[    5.275977] systemd[1]: Listening on Journal Socket.
[    5.290617] systemd[1]: Starting System Slice.
[    5.314919] systemd[1]: Created slice System Slice.
[    5.329355] systemd[1]: Starting File System Check on Root Device...
[    5.343306] usb 1-1.5: new high-speed USB device number 7 using dwc_otg
[    5.423883] systemd[1]: Starting system-systemd\x2dfsck.slice.
[    5.451603] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    5.468268] systemd[1]: Starting system-getty.slice.
[    5.495988] systemd[1]: Created slice system-getty.slice.
[    5.511805] systemd[1]: Starting system-serial\x2dgetty.slice.
[    5.534125] usb 1-1.5: New USB device found, idVendor=0cf3, idProduct=9271
[    5.534138] usb 1-1.5: New USB device strings: Mfr=16, Product=32, SerialNumber=48
[    5.534145] usb 1-1.5: Product: USB2.0 WLAN
[    5.534152] usb 1-1.5: Manufacturer: ATHEROS
[    5.534159] usb 1-1.5: SerialNumber: 12345
[    5.615695] systemd[1]: Created slice system-serial\x2dgetty.slice.
[    5.632114] systemd[1]: Starting Increase datagram queue length...
[    5.704035] systemd[1]: Starting Restore / save the current clock...
[    5.739281] systemd[1]: Mounting POSIX Message Queue File System...
[    5.783594] systemd[1]: Started Set Up Additional Binary Formats.
[    5.800161] systemd[1]: Mounting Debug File System...
[    5.829282] systemd[1]: Mounted Huge Pages File System.
[    5.845321] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[    5.883866] systemd[1]: Starting Load Kernel Modules...
[    5.913500] systemd[1]: Starting udev Coldplug all Devices...
[    5.942591] systemd[1]: Starting Slices.
[    5.967106] systemd[1]: Reached target Slices.
[    5.994717] systemd[1]: Mounted Debug File System.
[    6.023483] systemd[1]: Mounted POSIX Message Queue File System.
[    6.054545] systemd[1]: Started File System Check on Root Device.
[    6.091496] systemd[1]: Started Increase datagram queue length.
[    6.119139] systemd[1]: Started Restore / save the current clock.
[    6.147845] systemd[1]: Started Create list of required static device nodes for the current kernel.
[    6.179072] systemd[1]: Started Load Kernel Modules.
[    6.269558] systemd[1]: Time has been changed
[    6.313749] systemd[1]: Started udev Coldplug all Devices.
[    6.451015] systemd[1]: Starting Apply Kernel Variables...
[    6.503997] systemd[1]: Mounted FUSE Control File System.
[    6.520422] systemd[1]: Mounting Configuration File System...
[    6.534510] systemd[1]: Starting Create Static Device Nodes in /dev...
[    6.549507] systemd[1]: Starting Syslog Socket.
[    6.561259] systemd[1]: Listening on Syslog Socket.
[    6.561451] systemd[1]: Starting Journal Service...
[    6.587299] systemd[1]: Started Journal Service.
[    6.783011] systemd-udevd[134]: starting version 215
[    7.475712] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    8.243784] usb 1-1.2: ath9k_htc: Firmware ath9k_htc/htc_9271-1.4.0.fw requested
[    8.244096] usb 1-1.3: ath9k_htc: Firmware ath9k_htc/htc_9271-1.4.0.fw requested
[    8.244190] usb 1-1.4: ath9k_htc: Firmware ath9k_htc/htc_9271-1.4.0.fw requested
[    8.244288] usb 1-1.5: ath9k_htc: Firmware ath9k_htc/htc_9271-1.4.0.fw requested
[    8.244451] usbcore: registered new interface driver ath9k_htc
[    8.290368] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[    8.299718] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    8.452147] cfg80211: World regulatory domain updated:
[    8.452188] cfg80211:  DFS Master region: unset
[    8.452202] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
[    8.452219] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
[    8.452232] cfg80211:   (2457000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
[    8.452244] cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A)
[    8.452271] cfg80211:   (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
[    8.452306] cfg80211:   (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
[    8.452335] cfg80211:   (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
[    8.452351] cfg80211:   (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A)
[    8.452375] cfg80211:   (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
[    8.608487] usb 1-1.3: ath9k_htc: Transferred FW: ath9k_htc/htc_9271-1.4.0.fw, size: 51008
[    8.609182] usb 1-1.2: ath9k_htc: Transferred FW: ath9k_htc/htc_9271-1.4.0.fw, size: 51008
[    8.609834] usb 1-1.4: ath9k_htc: Transferred FW: ath9k_htc/htc_9271-1.4.0.fw, size: 51008
[    8.610500] usb 1-1.5: ath9k_htc: Transferred FW: ath9k_htc/htc_9271-1.4.0.fw, size: 51008
[    8.784072] random: nonblocking pool is initialized
[    8.841457] systemd-journald[132]: Received request to flush runtime journal from PID 1
[    9.603374] ath9k_htc 1-1.5:1.0: ath9k_htc: Target is unresponsive
[    9.603421] ath9k_htc: Failed to initialize the device
[    9.603904] usb 1-1.5: ath9k_htc: USB layer deinitialized
[    9.614619] ath9k_htc 1-1.2:1.0: ath9k_htc: HTC initialized with 33 credits
[    9.614690] ath9k_htc 1-1.4:1.0: ath9k_htc: HTC initialized with 33 credits
[    9.614727] ath9k_htc 1-1.3:1.0: ath9k_htc: HTC initialized with 33 credits
[    9.627897] ath: phy0: serialize_regmode is 0
[    9.627918] ath: phy0: UNDEFINED -> AWAKE
[    9.628013] ath: phy1: serialize_regmode is 0
[    9.628020] ath: phy1: UNDEFINED -> AWAKE
[    9.628130] ath: phy2: serialize_regmode is 0
[    9.628136] ath: phy2: UNDEFINED -> AWAKE
[    9.635903] ath: phy0: Reading from EEPROM, not flash
[    9.636027] ath: phy1: Reading from EEPROM, not flash
[    9.636135] ath: phy2: Reading from EEPROM, not flash
[    9.757995] Adding 102396k swap on /var/swap.  Priority:-1 extents:4 across:184316k SSFS
[    9.777157] ath: phy2: Read Magic = 0xA55A
[    9.777170] ath: phy2: need_swap = False
[    9.777178] ath: phy2: Eeprom VER: 14, REV: 13
[    9.777184] ath: phy2: Initialize ANI
[    9.777189] ath: phy2: Enable MIB counters
[    9.778031] ath: phy0: Read Magic = 0xA55A
[    9.778037] ath: phy0: need_swap = False
[    9.778043] ath: phy0: Eeprom VER: 14, REV: 15
[    9.778047] ath: phy0: Initialize ANI
[    9.778052] ath: phy0: Enable MIB counters
[    9.778149] ath: phy1: Read Magic = 0xA55A
[    9.778154] ath: phy1: need_swap = False
[    9.778162] ath: phy1: Eeprom VER: 14, REV: 13
[    9.778166] ath: phy1: Initialize ANI
[    9.778171] ath: phy1: Enable MIB counters
[    9.779157] ath: phy2: Setup TX queue: 9
[    9.779163] ath: phy2: Set queue properties for: 9
[    9.779169] ath: phy2: Setup TX queue: 8
[    9.779174] ath: phy2: Set queue properties for: 8
[    9.779180] ath: phy2: Setup TX queue: 1
[    9.779186] ath: phy2: Set queue properties for: 1
[    9.779191] ath: phy2: Setup TX queue: 0
[    9.779195] ath: phy2: Set queue properties for: 0
[    9.779200] ath: phy2: Setup TX queue: 2
[    9.779205] ath: phy2: Set queue properties for: 2
[    9.779210] ath: phy2: Setup TX queue: 3
[    9.779214] ath: phy2: Set queue properties for: 3
[    9.780033] ath: phy0: Setup TX queue: 9
[    9.780039] ath: phy0: Set queue properties for: 9
[    9.780044] ath: phy0: Setup TX queue: 8
[    9.780049] ath: phy0: Set queue properties for: 8
[    9.780054] ath: phy0: Setup TX queue: 1
[    9.780059] ath: phy0: Set queue properties for: 1
[    9.780063] ath: phy0: Setup TX queue: 0
[    9.780068] ath: phy0: Set queue properties for: 0
[    9.780073] ath: phy0: Setup TX queue: 2
[    9.780078] ath: phy0: Set queue properties for: 2
[    9.780083] ath: phy0: Setup TX queue: 3
[    9.780088] ath: phy0: Set queue properties for: 3
[    9.780150] ath: phy1: Setup TX queue: 9
[    9.780156] ath: phy1: Set queue properties for: 9
[    9.780162] ath: phy1: Setup TX queue: 8
[    9.780166] ath: phy1: Set queue properties for: 8
[    9.780171] ath: phy1: Setup TX queue: 1
[    9.780176] ath: phy1: Set queue properties for: 1
[    9.780181] ath: phy1: Setup TX queue: 0
[    9.780185] ath: phy1: Set queue properties for: 0
[    9.780190] ath: phy1: Setup TX queue: 2
[    9.780195] ath: phy1: Set queue properties for: 2
[    9.780200] ath: phy1: Setup TX queue: 3
[    9.780204] ath: phy1: Set queue properties for: 3
[   10.046232] ath: phy2: TX streams 1, RX streams: 1
[   10.048197] ath9k_htc 1-1.4:1.0: ath9k_htc: FW Version: 1.4
[   10.048213] ath9k_htc 1-1.4:1.0: FW RMW support: On
[   10.048222] ath: EEPROM regdomain: 0x809c
[   10.048226] ath: EEPROM indicates we should expect a country code
[   10.048232] ath: doing EEPROM country->regdmn map search
[   10.048236] ath: country maps to regdmn code: 0x52
[   10.048242] ath: Country alpha2 being used: CN
[   10.048246] ath: Regpair used: 0x52
[   10.049099] ath: phy0: TX streams 1, RX streams: 1
[   10.050192] ath9k_htc 1-1.3:1.0: ath9k_htc: FW Version: 1.4
[   10.050199] ath9k_htc 1-1.3:1.0: FW RMW support: On
[   10.050204] ath: EEPROM regdomain: 0x833a
[   10.050209] ath: EEPROM indicates we should expect a country code
[   10.050215] ath: doing EEPROM country->regdmn map search
[   10.050220] ath: country maps to regdmn code: 0x37
[   10.050225] ath: Country alpha2 being used: GB
[   10.050229] ath: Regpair used: 0x37
[   10.051313] ath: phy1: TX streams 1, RX streams: 1
[   10.051945] ath9k_htc 1-1.2:1.0: ath9k_htc: FW Version: 1.4
[   10.051953] ath9k_htc 1-1.2:1.0: FW RMW support: On
[   10.051957] ath: EEPROM regdomain: 0x809c
[   10.051962] ath: EEPROM indicates we should expect a country code
[   10.051967] ath: doing EEPROM country->regdmn map search
[   10.051971] ath: country maps to regdmn code: 0x52
[   10.051977] ath: Country alpha2 being used: CN
[   10.051981] ath: Regpair used: 0x52
[   10.080539] ath: phy0: WMI:1, BCN:2, CAB:3, UAPSD:4, MGMT:5, BE:6, BK:7, VI:8, VO:9
[   10.080556] ieee80211 phy0: Atheros AR9271 Rev:1
[   10.082154] ath: phy2: WMI:1, BCN:2, CAB:3, UAPSD:4, MGMT:5, BE:6, BK:7, VI:8, VO:9
[   10.082166] ieee80211 phy2: Atheros AR9271 Rev:1
[   10.095336] ath: phy1: WMI:1, BCN:2, CAB:3, UAPSD:4, MGMT:5, BE:6, BK:7, VI:8, VO:9
[   10.095365] ieee80211 phy1: Atheros AR9271 Rev:1
[   10.125594] cfg80211: Current regulatory domain intersected:
[   10.125625] cfg80211:  DFS Master region: unset
[   10.125633] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
[   10.125644] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
[   10.125651] cfg80211:   (2457000 KHz - 2482000 KHz @ 25000 KHz), (N/A, 2000 mBm), (N/A)
[   10.125657] cfg80211:   (2474000 KHz - 2482000 KHz @ 8000 KHz), (N/A, 2000 mBm), (N/A)
[   10.125669] cfg80211:   (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
[   10.125677] cfg80211:   (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
[   10.125684] cfg80211:   (5490000 KHz - 5710000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
[   10.125690] cfg80211:   (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
[   10.163036] cfg80211: Current regulatory domain intersected:
[   10.163061] cfg80211:  DFS Master region: unset
[   10.163069] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
[   10.163077] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
[   10.163085] cfg80211:   (2457000 KHz - 2482000 KHz @ 25000 KHz), (N/A, 2000 mBm), (N/A)
[   10.163091] cfg80211:   (2474000 KHz - 2482000 KHz @ 8000 KHz), (N/A, 2000 mBm), (N/A)
[   10.163098] cfg80211:   (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
[   10.163107] cfg80211:   (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
[   10.163113] cfg80211:   (57240000 KHz - 59400000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
[   10.163120] cfg80211:   (59400000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
[   10.174022] cfg80211: Current regulatory domain intersected:
[   10.174042] cfg80211:  DFS Master region: unset
[   10.174049] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
[   10.174058] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
[   10.174064] cfg80211:   (2457000 KHz - 2482000 KHz @ 25000 KHz), (N/A, 2000 mBm), (N/A)
[   10.174070] cfg80211:   (2474000 KHz - 2482000 KHz @ 8000 KHz), (N/A, 2000 mBm), (N/A)
[   10.174077] cfg80211:   (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
[   10.174085] cfg80211:   (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
[   10.174091] cfg80211:   (57240000 KHz - 59400000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
[   10.174097] cfg80211:   (59400000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
rodizio1 commented 7 years ago

Did another test on the clean image with the above patch.

Three cards were plugged in at bootup already, then plugged in the 4th card:

[   67.873274] usb 1-1.3: new high-speed USB device number 7 using dwc_otg
[   67.994550] usb 1-1.3: New USB device found, idVendor=0cf3, idProduct=9271
[   67.994573] usb 1-1.3: New USB device strings: Mfr=16, Product=32, SerialNumber=48
[   67.994585] usb 1-1.3: Product: UB91C
[   67.994598] usb 1-1.3: Manufacturer: ATHEROS
[   67.994639] usb 1-1.3: SerialNumber: 12345
[   67.996104] usb 1-1.3: ath9k_htc: Firmware ath9k_htc/htc_9271-1.4.0.fw requested
[   68.289608] usb 1-1.3: ath9k_htc: Transferred FW: ath9k_htc/htc_9271-1.4.0.fw, size: 51008
[   69.283254] ath9k_htc 1-1.3:1.0: ath9k_htc: Target is unresponsive
[   69.283329] ath9k_htc: Failed to initialize the device
[   69.284458] usb 1-1.3: ath9k_htc: USB layer deinitialized

usbmon capture: usbcap-with-patch-on-clean-image.zip

olerem commented 7 years ago

But 3 cards work stable now?

SunilMohanAdapa commented 7 years ago

I would like share my experiences in trying to use multiple AR9271 USB Wi-Fi dongles (TP-Link WN722N) with Olimex Olinuxino Lime 2 (OSHW).

When I tried to connect more than one USB dongle to one USB port (or even two USB ports) on the Lime2, I had issues with device showing up in lsusb but not in ifconfig. Then I used an unpower USB hub with mostly similar results.

Suspecting a power issue, I switched to a powered USB hub. I was able to work with at least 4 USB devices. When I insert the USB devices one after the other every thing works. I could even say they they work reliably. However, after a reboot they don't get detected. After a reboot sometimes only one device shows up. Removing one device and inserting it back again does gets all devices working again. There are no messages about the device detection in dmesg (such as "new high-speed USB device...").

Unfortunately, I am unable to provide logs at this moment. Please let me know if they will be useful so I can put in some time for that.

By the way, a huge thank you to @olerem and everyone else working on this project and Debian inclusion. AR9271 based dongles are the only solution I know of for free software Wi-Fi on single board computers. This means a lot to the FreedomBox project.

olerem commented 7 years ago

Hm... currently we start all adapters almost at once. According to wireshark capture it generate lots of traffic, especially the interrupt endpoint. By reducing number on Interrupt pipes looks like we can start at least 3 adapters at same time. @rodizio1 correct?

rodizio1 commented 7 years ago

Yes, three cards connected during boot-up worked. But I did not test very often, give me a day or two for more testing (also on the other image with the 1000Hz kernel) to really make sure it wasn't just coincidence.

rodizio1 commented 7 years ago

Did a lot more testing with both the clean image and the other with the 1000Hz Kernel.

Reducing the interrupt pipes didn't help. It was just that I was logged in over serialport and did not use the ethernet port (which is connected over usb on the pi ...). Three cards work as long as there is nothing else happening on the USB bus. Four cards never work.

olerem commented 7 years ago

Uff.. ok. Currently i don't have time to do own research on it. If you or some one else can do deeper investigation it will be great. Any one who will do it, need to solder uart on the adapter, to be able to see firmware messages.

olerem commented 7 years ago

@rodizio1 , is it your patch http://www.spinics.net/lists/linux-wireless/msg156697.html ?

rodizio1 commented 7 years ago

Not using any patches, just changed the kernel .config to use 1000Hz. So using 1000Hz should actually make it better?

Have tried soldering some wires to the Atheros Chip for serial debugging. Failed miserably, card is toast now :(

olerem commented 7 years ago

Yes and not, 1000Hz would increase system/interrupt load. But change behavior of timeout for this driver... Any way, this patch went upstream. I hope it will make things better for you. Sorry, TP-Link is hard to solder.. :(

melyux commented 7 years ago

Hey @rodizio1, did you ever find a solution to this? I'm having the same troubles with the 3 AR9271 cards + 1 ethernet adapter on the same hub. Was previously working with 2 AR9271 cards + 1 non-AR9271 card + 1 ethernet adapter, just not with 3 of AR9271 ones. Getting the same errors as you.

And in the same way as you, if I don't have the 4th device plugged in (the ethernet adapter), the 3 cards work fine, but as soon as there are 4 devices on the hub, one of them stops working. Sometimes, the ethernet adapter is one of those things. But if AR9271 cards make up 2 or fewer of the 4 devices, then there are no problems, even if all 4 ports are being used.

Apart from what you guys have discussed above, I only found this VirtualBox ticket, where someone attributes this to:

The ath9k_htc driver is poorly written and schedules bulk transfers on interrupt endpoints.

which you seem to have mentioned above already.

melyux commented 7 years ago

@rodizio1 Disregard that, I hadn't read carefully once again. I'll apply the patch and see what happens. Have you had luck with it?

melyux commented 7 years ago

I applied the patch from the link and confirmed it was patched, but the problem persists in the exact same way when using more than 2 AR9271 cards. Which is weird because it was pulled into the upstream already...

[   56.784735] usb 1-1.4: Service connection timeout for: 256
[   56.784813] ath9k_htc 1-1.4:1.0: ath9k_htc: Unable to initialize HTC services
[   56.784912] ath9k_htc: Failed to initialize the device
[   56.788045] usb 1-1.4: ath9k_htc: USB layer deinitialized

The patch is supposed to make it timeout after 1 second instead of 0.1 seconds, but judging by the log, there's no change in the time before the the "Service connection timeout" occurs, which is around 300 ms. I changed the code to 3 seconds, 5 seconds, and 10 seconds, and it has no effect at all, it still times out after less than a second.

melyux commented 7 years ago

Got it working. I did a sudo apt-get upgrade on the Raspberry Pis. This moved me from 4.9.13+ kernel (which I had gotten from rpi-update... hmm) to the version which I believe is included in this month's new release of Raspbian, 4.4.50+. After reboot, all 3 AR9271 devices worked on the same hub, no problem.

I went back to rpi-update and saw that it says it updated the kernel to 4.9.y and this message:

Be aware there could be compatibility issues with some drivers Discussion here: https://www.raspberrypi.org/forums/viewtopic.php?f=29&t=167934

I wonder why this is. Isn't 4.9.13+ supposed to be ahead of 4.4.50+? I hope this issue won't seep into a stable kernel in the future.

EDIT: After some repositioning of the USB plugs in their respective ports, we're back to not initialization failure on more than 3 AR9271 devices, even on this kernel. Luckily, I had made an SD card image right after I got it to work on 4.4.50. I restored to it, and now it works again. Sometimes, they all come up, but then the shell crashes when I try to put one in monitor mode, and also if I try to run ifconfig.

EDIT2: I seem to have found a tenuous workaround (after applying the patch) for the 3 cards, at least for the last 2 boots. On a fresh install of 4.4.50 kernel Raspbian Lite, I do the following:

  1. Set the ethernet to static IP (because there seems to be an issue where all 3 cards and the ethernet starts, but we get a dhcpcd.service start operation timed out. Terminating. error in dmesg and there is no connection).

  2. Boot with the 4th device (USB ethernet) unplugged and all 3 AR9271 cards plugged in, and wait for all their LEDs to come up to indicate that they have all been initialized.

  3. Unplug one of the cards and plug in the ethernet.

  4. ssh in and put the remaining two cards into monitor mode (this seems to avoid the problem when you have all 3 cards in normal managed mode and try to put one of them into monitor mode, where the device seems to lose its ability to do everything except perform read commands and brings up no prompt when SSHing back in).

  5. Plug in the 3rd card we just unplugged, and then put that into monitor mode as well. Then they all seem to work.

rodizio1 commented 7 years ago

Sorry for my late reply melikyuksel, didn't realize you were posting here.

Well, what you describe is exactly what I'm seeing. It appears to be more or less random and also being dependent on other stuff using the USB bus.

Three cards is 99% now for me, as long as I make sure no other stuff is running during card initialization and no network cable is plugged. Oh and LED blinking disabled.

Maybe we should open another issue on the Raspberry Linux kernel Github.

melyux commented 7 years ago

@rodizio1 Sounds like a good idea. This does seem to be limited to Raspberry Pi kernels; I assume Kali Linux for Raspberry Pi also uses the same kernel as Raspbian, since it has the problem as well. According to the mailing list, it used to be a problem for all of the Linux kernel, but was fixed with that patch above; but applying that patch doesn't fix it for Raspberry Pi, so it must depend on some other new development that the Pi kernel doesn't have yet... or it's a hardware thing. I'll try it out with Arch Linux on the Pi and see what happens. If not, I'll submit an issue on raspberrypi/linux, unless you want to be proactive. :)

sumeetkpatel commented 7 years ago

I am also struggling with 4X antenna setups using TPLink W722N. I am trying to create a device that I can reboot and have all the cards come up reliably on kernel 4.x (3.x works oddly enough), I am simply at a loss at what is happening so started collecting details about whats happening.

I am not seeing the exact same errors as OP, but rather am having trouble initializing the devices at startup altogether, in the scenarios where all 4 cards work, we haven't noticed any problems (yet) during monitor mode. Perhaps it could be related?

I can confirm that power hasn't been an issue at all, as running powered USB hubs, using multi-meters and myriads of hub setups has had no hugely positive results and many times I have had the four cards working all on single hub from a single USB port without additional power.

I would note here that our experience with OTG USB such as the one on the Raspberry Pi (both 1 and 2) provoked the issue so badly that we moved to devices that do not use OTG such as the OrangePi Lite as we suspected the OTG just cant handle so many USB devices and especially in this manner.

I would note also that we have had similar issues on other devices, even with a proper USB hub, such as the new ASUS Tinkerboard, OrangePi Lite, and OrangePi Zero.

Funnily enough, we have no issues with the x86 based Intel Compute Stick, but is an expensive device. I did however have problems with Ubuntu Server 16 as a Virtual Box Guest on a Macbook Pro and Natively as well, but had 4 cards working similarly to my ARM Orange Pi Lite setup described below where I connect the devices after booting.

We have had less issues on ARM based systems with the Ralink based Mediatek (mt7601u) setup, but is still problematic and unrelated.

So using the OrangePi Lite we do not have issues using 3.x based Armbian or DietPi based distro.

I am including information on my current setup in development, the OrangePiLite / Armbian nightly Kernel 4.11:

I have not yet tried compiling the driver yet with debug enabled.

I also have 6+ dongles available to further provoke or test the limitations as needed.

I have tried blacklisting ath9k_htc in a modprobe conf, and then modprobing to restore them to simulate the delay, but get the same problem as the booting behavior where only 2 or so cards become available.

Output and Logs: ath9k_htc x4.tar.gz

Update 1: I tried compiling the latest driver on an x86 system and transferring the firmware files and rebooting, doesn't seem to have made any difference.

vk-gst commented 6 years ago

I am trying to interface TL-WN722N with Angstrom Image on a Cyclone V SoC. I have built the module as static and initialized the firmware. I am using the following kernel version : 4.1.33-ltsi-altera . I observe the following error now :

[   14.568484] usb 1-1: ath9k_htc: Transferred FW: ath9k_htc/htc_9271-1.4.0.fw, size: 51008
[   14.820407] ath9k_htc 1-1:1.0: ath9k_htc: HTC initialized with 33 credits
[   15.852173] ath: phy0: Mac Chip Rev 0x0f.3 is not supported by this driver
[   15.859064] ath: phy0: Unable to initialize hardware; initialization status: -95
[   15.866512] ath: phy0: Unable to initialize hardware; initialization status: -95
[   15.873973] ath9k_htc: Failed to initialize the device

I had a read over the linux drivers for ath9k_htc on the official website for TP-Link(the manufacture of wifi dongle), and it says that the ath9k drivers are officially only available for the version 2 of the device. The TL-WN722N is a version 1 device as per the details on the website.

Has anyone faced such an issue. Note: The version can be identified by reading the FCC ID printed on the device, it suffixes v2 specifically for a version 2 device and none for version 1 devices.

melyux commented 6 years ago

I think this can be tentatively be closed, now that this was fixed at the end of https://github.com/raspberrypi/linux/issues/2023. Or we could keep it open until the kernel that fixes it becomes stable so rpi-update will not be necessary, or until the the /boot/cmdline.txt change is not needed (ever)?

olerem commented 6 years ago

Do i see it correctly, the fix is related to RPi (or dw) USB host controller and not to atheros driver or firmware?

psyborg55 commented 6 years ago

config ATH9K_AHB

This option enables the AHB bus support in ath9k.

  Say Y, if you have a SoC with a compatible built-in
  wireless MAC. Say N if unsure.

regardless of the USB bus in htc case, AR9271 has built-in wifi mac. maybe some AHB support code could handle these issues properly?

dagf2101 commented 5 years ago

I found some sort of workaround to my multiple adapter problem,

Using kernel 4.19 and two adapters plugged in, I had one of the two adapters failing maybe once every 5-10 reboots.

Once in that state, I tried so many things to completly restart the card or pc or turn off USB power without success, but finally managed to do it using a realtimeclock wake alarm.

It may be not implemented on every systems but on my NUC pc I do the following:

!/bin/bash

echo 0 > /sys/class/rtc/rtc0/wakealarm echo date '+%s' -d '+ 10 seconds' > /sys/class/rtc/rtc0/wakealarm shutdown -h now

The system will shut down and in my case TURN OFF THE USB POWER, and then restart after 10 seconds. Just make a script at boot to automate this until all the adapters are working.

I know this is not ideal but im my case that is a acceptable workaround to make the device boot in a working state.