Wifi not working on first reboot after firmware upgrade

Hi,

I have the issue that the wifi is not working on the first (automatic) reboot after a firmware upgrade on my FritzBox 7330. I have to manually restart wlan0 from the web interface or do another reboot (on all adjacent reboots the wifi starts without manual intervention).

I compared the two kernel logs (auto reboot after upgrade and a manual reboot) and the only real difference I've found is:

[   65.973024] owl-loader 0000:00:0e.0: Direct firmware load for ath9k-eeprom-pci-0000:00:0e.0.bin failed with error -2
[   65.982121] owl-loader 0000:00:0e.0: Falling back to user helper

Does someone has an idea how to fix this? It's not the first time I encounter this issue and it would be great if I could upgrade the firmware without crouching into a small corner afterwards to connect my Laptop via cable to get the wifi working :laughing:

Full kernel log:

[    0.000000] Linux version 4.9.184 (sven@archdesk) (gcc version 7.3.0 (OpenWrt GCC 7.3.0 r7808-ef686b7292) ) #0 Thu Jun 27 12:18:52 2019
[    0.000000] SoC: AR9 rev 1.2
[    0.000000] bootconsole [early0] enabled
[    0.000000] CPU0 revision is: 0001954c (MIPS 34Kc)
[    0.000000] MIPS: machine is 1&1 HomeServer
[    0.000000] Determined physical RAM map:
[    0.000000]  memory: 04000000 @ 00000000 (usable)
[    0.000000] Initrd not found or empty - disabling initrd
[    0.000000] Primary instruction cache 32kB, VIPT, 4-way, linesize 32 bytes.
[    0.000000] Primary data cache 16kB, 4-way, VIPT, no aliases, linesize 32 bytes
[    0.000000] Zone ranges:
[    0.000000]   Normal   [mem 0x0000000000000000-0x0000000003ffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x0000000003ffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x0000000003ffffff]
[    0.000000] On node 0 totalpages: 16384
[    0.000000] free_area_init_node: node 0, pgdat 804d1844, node_mem_map 810062c0
[    0.000000]   Normal zone: 128 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 16384 pages, LIFO batch:3
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
[    0.000000] Kernel command line: console=ttyLTQ0,115200
[    0.000000] PID hash table entries: 256 (order: -2, 1024 bytes)
[    0.000000] Dentry cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Inode-cache hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Writing ErrCtl register=000332c0
[    0.000000] Readback ErrCtl register=000332c0
[    0.000000] Memory: 58532K/65536K available (3844K kernel code, 163K rwdata, 920K rodata, 1200K init, 209K bss, 7004K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS:256
[    0.000000] CPU Clock: 393MHz
[    0.000000] clocksource: MIPS: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 9721189849 ns
[    0.000014] sched_clock: 32 bits at 196MHz, resolution 5ns, wraps every 10922685437ns
[    0.007948] Calibrating delay loop... 260.86 BogoMIPS (lpj=521728)
[    0.042435] pid_max: default: 32768 minimum: 301
[    0.047303] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.053835] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.067537] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.077197] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.083409] pinctrl core: initialized pinctrl subsystem
[    0.089427] NET: Registered protocol family 16
[    0.098637] pinctrl-xway 1e100b10.pinmux: Init done
[    0.104685] dma-xway 1e104100.dma: Init done - hw rev: 6, ports: 5, channels: 20
[    0.171164] PCI host bridge /fpi@10000000/pci@E105400 ranges:
[    0.176836]  MEM 0x0000000018000000..0x0000000019ffffff
[    0.182081]   IO 0x000000001ae00000..0x000000001affffff
[    0.218576] usbcore: registered new interface driver usbfs
[    0.224106] usbcore: registered new interface driver hub
[    0.229453] usbcore: registered new device driver usb
[    0.234800] PCI host bridge to bus 0000:00
[    0.238816] pci_bus 0000:00: root bus resource [mem 0x18000000-0x19ffffff]
[    0.245723] pci_bus 0000:00: root bus resource [io  0x1ae00000-0x1affffff]
[    0.252666] pci_bus 0000:00: root bus resource [??? 0x00000000 flags 0x0]
[    0.259523] pci_bus 0000:00: No busn resource found for root bus, will use [bus 00-ff]
[    0.267585] pci 0000:00:0e.0: [168c:ff1d] type 00 class 0x020000
[    0.267633] pci 0000:00:0e.0: reg 0x10: [mem 0x00000000-0x0000ffff]
[    0.268112] pci_bus 0000:00: busn_res: [bus 00-ff] end is updated to 00
[    0.268159] pci 0000:00:0e.0: BAR 0: assigned [mem 0x18000000-0x1800ffff]
[    0.275929] clocksource: Switched to clocksource MIPS
[    0.282513] NET: Registered protocol family 2
[    0.288041] TCP established hash table entries: 1024 (order: 0, 4096 bytes)
[    0.294935] TCP bind hash table entries: 1024 (order: 0, 4096 bytes)
[    0.301330] TCP: Hash tables configured (established 1024 bind 1024)
[    0.307971] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.313702] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.320341] NET: Registered protocol family 1
[    0.324697] PCI: CLS 0 bytes, default 32
[    0.332926] gptu: totally 6 16-bit timers/counters
[    0.337806] gptu: misc_register on minor 63
[    0.341900] gptu: succeeded to request irq 126
[    0.346382] gptu: succeeded to request irq 127
[    0.350895] gptu: succeeded to request irq 128
[    0.355409] gptu: succeeded to request irq 129
[    0.359932] gptu: succeeded to request irq 130
[    0.364437] gptu: succeeded to request irq 131
[    0.369995] Crashlog allocated RAM at address 0x3f00000
[    0.377602] workingset: timestamp_bits=30 max_order=14 bucket_order=0
[    0.395542] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.401282] jffs2: version 2.2 (NAND) (SUMMARY) (LZMA) (RTIME) (CMODE_PRIORITY) (c) 2001-2006 Red Hat, Inc.
[    0.428908] io scheduler noop registered
[    0.432737] io scheduler deadline registered (default)
[    0.438629] 1e100c00.serial: ttyLTQ0 at MMIO 0x1e100c00 (irq = 112, base_baud = 0) is a lantiq,asc
[    0.447557] console [ttyLTQ0] enabled
[    0.454803] bootconsole [early0] disabled
[    0.463812] lantiq nor flash device: 01000000 at 10000000
[    0.467977] ltq_nor: Found 1 x16 devices at 0x0 in 16-bit bank. Manufacturer ID 0x0000c2 Chip ID 0x00227e
[    0.477258] Amd/Fujitsu Extended Query Table at 0x0040
[    0.482354]   Amd/Fujitsu Extended Query version 1.3.
[    0.487343] number of CFI chips: 1
[    0.490757] 4 fixed-partitions partitions found on MTD device ltq_nor
[    0.497094] Creating 4 MTD partitions on "ltq_nor":
[    0.501925] 0x000000000000-0x000000020000 : "urlader"
[    0.511313] 0x000000020000-0x000000f80000 : "firmware"
[    0.537568] 2 eva-fw partitions found on MTD device firmware
[    0.541794] 0x000000020000-0x0000001aa268 : "kernel"
[    0.549026] 0x0000001b0100-0x000000f80000 : "rootfs"
[    0.555293] mtd: device 3 (rootfs) set to be root filesystem
[    0.559594] 1 squashfs-split partitions found on MTD device rootfs
[    0.565646] 0x000000440000-0x000000f80000 : "rootfs_data"
[    0.573851] 0x000000f80000-0x000000fc0000 : "tffs (1)"
[    0.580443] 0x000000fc0000-0x000001000000 : "tffs (2)"
[    0.589252] libphy: Fixed MDIO Bus: probed
[    0.601369] libphy: ltq_mii: probed
[    0.603667] Generic PHY 1e180000.etop-ffffffff:00: attached PHY driver [Generic PHY] (mii_bus:phy_addr=1e180000.etop-ffffffff:00, irq=-1)
[    0.617332] wdt 1f8803f0.watchdog: Init done
[    0.623272] NET: Registered protocol family 10
[    0.633766] NET: Registered protocol family 17
[    0.636895] 8021q: 802.1Q VLAN Support v1.8
[    0.646924] OF: fdt:not creating '/sys/firmware/fdt': CRC check failed
[    0.657552] VFS: Mounted root (squashfs filesystem) readonly on device 31:3.
[    0.665308] Freeing unused kernel memory: 1200K
[    0.668401] This architecture does not have kernel memory protection.
[    1.120215] random: fast init done
[    1.831420] init: Console is alive
[    1.833811] init: - watchdog -
[    3.269994] kmodloader: loading kernel modules from /etc/modules-boot.d/*
[    3.530070] dwc2 1e101000.ifxhcd: DWC OTG Controller
[    3.533703] dwc2 1e101000.ifxhcd: new USB bus registered, assigned bus number 1
[    3.540917] dwc2 1e101000.ifxhcd: irq 62, io mem 0x00000000
[    3.548052] hub 1-0:1.0: USB hub found
[    3.550906] hub 1-0:1.0: 1 port detected
[    3.556044] kmodloader: done loading kernel modules from /etc/modules-boot.d/*
[    3.572367] init: - preinit -
[    4.583111] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    4.610924] random: procd: uninitialized urandom read (4 bytes read)
[    7.648194] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[    8.104967] jffs2_scan_eraseblock(): End of filesystem marker found at 0x20000
[    8.110784] jffs2_build_filesystem(): unlocking the mtd device... 
[    8.116676] done.
[    8.118537] jffs2_build_filesystem(): erasing all blocks after the end marker... 
[   52.833865] random: crng init done
[   63.466854] done.
[   63.467388] jffs2: notice: (359) jffs2_build_xattr_subsystem: complete building xattr subsystem, 0 of xdatum (0 unchecked, 0 orphan) and 0 of xref (0 dead, 0 orphan) found.
[   63.485064] mount_root: overlay filesystem has not been fully initialized yet
[   63.498707] mount_root: switching to jffs2 overlay
[   63.972877] urandom-seed: Seed file not found (/etc/urandom.seed)
[   64.141735] procd: - early -
[   64.143360] procd: - watchdog -
[   64.840871] procd: - watchdog -
[   64.843142] procd: - ubus -
[   65.138726] procd: - init -
[   65.750367] kmodloader: loading kernel modules from /etc/modules.d/*
[   65.761709] NET: Registered protocol family 8
[   65.764677] NET: Registered protocol family 20
[   65.777746] PPP generic driver version 2.4.2
[   65.790032] ip6_tables: (C) 2000-2006 Netfilter Core Team
[   65.808373] IFX MEI Version 5.00.00
[   65.821156] Infineon CPE API Driver version: DSL CPE API V3.24.4.4
[   65.834484] Loading modules backported from Linux version wt-2017-11-01-0-gfe248fc2c180
[   65.841069] Backport generated by backports.git v4.14-rc2-1-31-g86cf0e5d
[   65.851891] ip_tables: (C) 2000-2006 Netfilter Core Team
[   65.862459] Infineon Technologies DEU driver version 2.0.0 
[   65.869156] IFX DEU DES initialized (multiblock).
[   65.873830] IFX DEU AES initialized (multiblock).
[   65.877682] IFX DEU ARC4 initialized (multiblock).
[   65.882193] IFX DEU SHA1 initialized.
[   65.885773] IFX DEU MD5 initialized.
[   65.889353] IFX DEU SHA1_HMAC initialized.
[   65.893340] IFX DEU MD5_HMAC initialized.
[   65.905647] nf_conntrack version 0.5.0 (1024 buckets, 4096 max)
[   65.964655] PCI: Enabling device 0000:00:0e.0 (0000 -> 0002)
[   65.973024] owl-loader 0000:00:0e.0: Direct firmware load for ath9k-eeprom-pci-0000:00:0e.0.bin failed with error -2
[   65.982121] owl-loader 0000:00:0e.0: Falling back to user helper
[   66.101889] NET: Registered protocol family 24
[   66.128101] xt_time: kernel timezone is -0000
[   66.276458] kmodloader: done loading kernel modules from /etc/modules.d/*
[   98.081767] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[  101.288284] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[  110.019104] owl-loader 0000:00:0e.0: fixup device configuration
[  110.025703] pci 0000:00:0e.0: [168c:002d] type 00 class 0x028000
[  110.030358] pci 0000:00:0e.0: reg 0x10: [mem 0x18000000-0x1800ffff]
[  110.036603] pci 0000:00:0e.0: PME# supported from D0 D3hot
[  110.042385] pci 0000:00:0e.0: BAR 0: assigned [mem 0x18000000-0x1800ffff]
[  110.048870] PCI: Enabling device 0000:00:0e.0 (0000 -> 0002)
[  110.098685] ath: EEPROM regdomain: 0x8114
[  110.101295] ath: EEPROM indicates we should expect a country code
[  110.107307] ath: doing EEPROM country->regdmn map search
[  110.112561] ath: country maps to regdmn code: 0x37
[  110.117302] ath: Country alpha2 being used: DE
[  110.121702] ath: Regpair used: 0x37
[  110.141755] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
[  110.153483] ieee80211 phy0: Atheros AR9287 Rev:2 mem=0xb8000000, irq=30
[ 3739.482778] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 3741.670024] wlan0: authenticate with 54:67:51:56:74:53
[ 3741.696328] wlan0: send auth to 54:67:51:56:74:53 (try 1/3)
[ 3741.716343] wlan0: authenticated
[ 3741.739126] wlan0: associating with AP with corrupt probe response
[ 3741.744054] wlan0: associate with 54:67:51:56:74:53 (try 1/3)
[ 3741.767310] wlan0: RX AssocResp from 54:67:51:56:74:53 (capab=0x1411 status=0 aid=5)
[ 3741.774046] wlan0: associated
[ 3741.776925] wlan0: Limiting TX power to 20 (20 - 0) dBm as advertised by 54:67:51:56:74:53
[ 3741.921127] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

This behavior is almost normal as your new rootfs doesn't include the firmware for your wifi card...
As you see with "falling back to user space helper" this gets extracted from your flash on first boot and it seems this is very slow, so the initialisation of your wifi device comes before your firmware is extracted by the user space helper.

You can add the file "/lib/firmware/ath9k-eeprom-pci-0000:00:0e.0.bin" to your /etc/sysupgrade.conf to backup and restore your firmware on sysupgrade and prevent the slow extraction from flash on upgrade.

Edit: but note that if you restore a backup of your device on another but identical device, this has it's own firmware file because there is some calibration data included that is device specific.

This issue has been fixed in upcoming 19.07. Now firmware loads fast enough to be in-place in time.

With current 18.06 release you can run wifi command after re-flash to enable Wi-Fi.
Or you can manually update a script in your device for faster loading.

@juppin Thanks I'll try that the next time. But I'm curious, why does it need to load a firmware while the kernel supports ath9k?

@Pilot6 Good to know that this issues has been addressed in 19.07. Whats the exact file that needs to be modified?

/etc/hotplug.d/firmware/

There are two scripts for ath9k and ath10k. Now dd command is updated to be faster.

See

1 Like

For ath9k it's not really a firmware, this is only a device specific calibration data that the driver needs for legal operation.

For some other cards there is really a firmware (non open source software that runs directly on the wifi device) that needs to be loaded on / before device initialisation.
Many devices with open source drivers needs closed source firmware for there operation.

@Pilot6 @juppin Thank you!

If you manually change the script, you'll have to add it to sysupgrade.conf, ot it is useless on a new flash.