Connecting to the saved network
※ router lights, a morning and a night
One morning the Booklet stopped joining my WiFi. The profile for my router was saved, the password was in the keyring, and when I pressed Connect in the wireless window it said "Connecting to the saved network." and then did nothing at all, for as long as I cared to watch. I tried five or six times, rebooted, tried again, and got the same result every time. Nothing had changed in Rime's code since the last time it worked, and nothing had changed in the router either, which left me with a machine that had decided on its own to stop doing something it had done every day for weeks.
The Booklet also has a TP-Link USB Ethernet adapter, which stays up whatever the WiFi does, so I could reach it over SSH and look at it from the Mac. That night, after one more reboot, I asked wifictl to connect from the shell instead of the WiFi Monitor window:
WiFi: connecting with saved profile 2
WiFi: connecting, attempt 1
Connection: connected, attempts 1, reconnects 0, link losses 0
Network SSID: testing, channel 1, BSSID e4:36:ac:2a:dc:f2
It took a second and a half, DHCP handed out the usual address, and I could log in over the wireless link as well. A bug that goes away as soon as somebody looks at it is a classic of the genre, and it usually means the interesting state was lost on the way, in this case with the reboot, since the kernel log only goes back to the last boot.
The next boot was more cooperative. Connect stalled in the window again and then, after ten seconds or so, worked, and wifictl status showed that the connection service, wifid, had made five attempts behind the window's back. A few rounds of disconnecting and connecting from a script on the Mac produced more of the same, and the card kept a record of the last attempt that failed:
Last card failure: receive/calibration failure; peer reason 0
Retained failure: RX calibration failed, TX transmission aborted,
join connection test aborted; 0 frames, 0 beacons
Before the AR9280 listens for anything, the driver calibrates it, and one of the steps measures the noise floor of the channel. Two checks can fail that step, a deadline of one second for the measurement and a limit of -97 dBm for the value it reads. The second antenna chain read -104 dBm on every good join, which is only 7 dB away from that limit, and the channels next to channel 1 had a few neighbours on them. It was a tidy theory. Mornings are busy, the noise goes up, the measurement fails, and after midnight, when I was testing, the neighbours are asleep and everything works. I wrote it down, added the calibration stage and the noise values to the failure record so the next failure would say which check it was, and went to bed reasonably pleased with myself.
wifid retries a failed attempt after 2, 4, 8 and 16 seconds and then every 30, and it never gives up. The window doesn't show the retries, only its last notice, so from the outside a failing connection and a slow one look the same, and both look like nothing.
The new record was on the Booklet an hour later, on a fresh boot, and the first connect failed in a way it hadn't shown before. There was no card failure at all. The driver reported its receive path and its join as never started, and wifiinfo explained why:
WiFi: probe deadline expired
EEPROM: not read, base word 0x100, 499 words read
EEPROM failed word: 0x2f3, status 0xffffffff
When the driver starts a session, it first probes the card, and the probe reads the card's EEPROM, 1628 words of calibration and board data, one word at a time through a status register. The whole probe ran under one deadline of 500 ms. The deadline exists to catch a dead bus, and after it passes, every register read returns 0xffffffff, which is where the status above came from. A probe that times out leaves the card not ready, the driver refuses to start a session on a card that isn't ready, and every retry from wifid probed again under the same 500 ms. On this boot it passed on the eighth attempt, about two minutes later. On a bad morning it might never pass, which fits five or six tries and a reboot better than any noise floor does.
ath9k, the Linux driver for the same chip, waits for each EEPROM word separately, with its own timeout. Rime does the same now, a timed out refresh keeps the EEPROM image it already read instead of reading all 1628 words again, and the probe records how long the read took. The first boot with the fix printed this:
EEPROM read time: 542555 us, slowest word 0x109 took 506 us
A healthy read of the EEPROM took longer than the deadline it had to fit in. Over the next few boots the same read took 435 ms and then 1.63 s, so for weeks every boot had been a coin toss, and that morning had simply lost several in a row.
That left the noise floor, which with the new record turned out to be a timeout every time, never a high value. ath9k doesn't wait for the measurement at all when it resets the card. It starts it, lets the radio run, and loads the result later, so I made Rime do the same and load the nominal value of -112 dBm when the measurement was late. The load then timed out instead, because the card doesn't accept a load while it is still measuring, and the comments in ath9k warn that writing over a measurement in progress can make the receiver deaf. So I tried skipping the load as well and kept the nominal value that was already in place.
The next run took seven minutes for four connect cycles. In two of them the calibration finished without complaint, the session started, and the radio sat there for its full 45 second deadline without receiving a single frame, with my router 44 dB away on the same channel. Each of those cycles took three attempts and 103 seconds, which is a long time to wait for a laptop to join a network in the same room.
That was the useful result. A noise floor measurement that never finishes means a receiver that hears nothing, and calibration had been right to fail all along. I took the nominal value out again and kept the one second deadline. The driver now fails such an attempt straight away, and wifid resets the radio at once up to three times before its normal backoff, since a full reset had cleared the deaf state every time. Ten cycles after that all connected, the slowest in seven seconds, but about a third of the resets still came up deaf, and seven seconds is still a long time for a laptop to join a network in the same room.
I had no idea why a reset would come up deaf, so the driver now reads 276 registers when a noise floor measurement ends, once for the last one that finished and once for the last one that stalled, and wifictl prints both. The ranges are those of ath9k's register dump in debugfs. A stall turned up on the third cycle, and the two dumps differed in six registers:
0x984c stall 0x0000233c good 0x015a233c
0x9860 stall 0x00068d22 good 0x00068d20
0x9864 stall 0x1901cf9c good 0x18b1cf9c
and the same three on the second chain. 0x9860 still had its measurement bit set and 0x9864 still held the nominal -112, which only confirmed what I knew. 0x984c is written as 0x0040233c from the same table ath9k uses, and on a good reset the card replaces the top half with a value of its own. On the stalled one the top half read zero, on both chains. Everything else, the synthesizer, the PLL, the gains, the chain masks, was the same in both dumps, which ruled out a mistake in what Rime writes and left me with two identical resets that ended differently.
ath9k's dump skips the analog registers from 0x7800, but ath9k reads them every time it changes a field in one of them, so I added those 40 to the dump as well. Most of them read back what was written. Four held results of the card's own calibration, which were saturated or empty after the stalled reset, and one was plain storage that no later write touches:
0x7828 stall 0xdb004012 good 0xdb005012 written 0xdb005012
Bit 12 of what I take to be the RX bias word of the second chain was gone, and it was gone in four stalls out of four, while the same word on the first chain was always right. I couldn't tell what the bit does, because neither the datasheets I have nor ath9k name it, but a radio that loses part of its bias on one chain and then hears nothing on both made the connection for me.
The obvious suspect was a write that didn't land, since the analog registers sit behind a serial shift interface that needs 100 µs after each write. The driver now reads the word back at the end of the preparation, before calibration starts, and it was correct every time, so the bit was lost later. Between that read and the noise floor measurement the driver writes no analog register at all, and only three things happen, the PHY is switched on, the AGC and filter calibration runs, and the nominal noise floor is loaded. I made the driver check the word after each of them, and the next run named the culprit four times out of four:
Retained calibration: register readback failed, stage AGC/filter calibration,
42018 us; register 00007828/db004012
The AGC and filter calibration is the one step where the card writes analog registers on its own, and on about every second or third reset it writes this one wrong. Rime runs that step in the same order and with the same bits as ath9k's ar9002_hw_init_cal, and when the step fails to finish, ath9k logs a message that ends in "noisy environment?", with the question mark. ath9k never reads the word back, so on Linux this reset would presumably go deaf in the same way and be rescued later by a watchdog.
The last change was a small one. When the calibration loses the bit, the driver writes both bias words back and runs the AGC and filter calibration again, in place, up to three times, before it gives up on the attempt and lets wifid reset the card. I didn't know whether the chip would accept that, since ath9k never tries it, but the next ten cycles answered the question:
cycle 2: 1s, attempts 1; Calibration: running; stage IQ calibration;
AGC/filter calibration ran again
All ten joined on the first attempt in a second or less, and five of them needed the second calibration to get there. The window now also says "Waiting for the wireless card" when the probe hasn't passed, instead of showing "Connecting" while nothing happens.
Two things cost me more time than they should have. For a while I tested from a loop in zsh, which, unlike Bash, doesn't split an unquoted variable into words, so ssh $S rime passed all my SSH options as one argument and every connection failed. The loop dutifully reported 23 clean cycles in a row, all of them imaginary, until I noticed that the kernel log had no record of any of them. The other was the noise floor, which I had blamed on my neighbours twice, once for being noisy and once for the radio being deaf, and which turned out to be the only part of the driver that had told the truth from the start.
What I still don't know is why the chip clears that bit, or what the bit is for. The driver now catches it within about 60 ms and puts it back, and the Booklet joins my router in about a second, which is what it did before all this started, except that now I know it was getting lucky.