Doesn't finish booting after flash?
peteruithoven opened this issue · 27 comments
After flashing a WiFi-Box with a new image (using our Run.sh) keeping the settings (without the -n
argument) it keeps flashing the big button, probably indicating that a boot process doesn't finish.
The box is accessible through ssh and the web interface loads.
API/d3dapi/network/status
indicated:
{
"data":
{
"bssid": "10:FE:ED:4C:CE:92",
"channel": 11,
"encryption": "none",
"localip": "192.168.10.1",
"mode": "ap",
"noise": -95,
"quality_max": 70,
"ssid": "Doodle3D-4CCE92",
"status": "",
"statusMessage": "",
"txpower": 15
},
"status": "success"
}
Firmware's log (/tmp/wifibox.log
) only contains:
CGI invocation
06-05 10:48:43 (info) =======rest api (api debugging)=======
06-05 10:48:43 (info) Doodle3D version: 0.10.5-a
06-05 10:48:43 (info) running in autowifi mode
06-05 11:21:13 (info) =======rest api (api debugging)=======
06-05 11:21:14 (info) received request of type GET for network/status
06-05 11:21:14 (info) remote IP/port: 192.168.5.220/58179
06-05 11:21:14 (info) network:getStatus
Logread contains:
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.000000] Linux version 3.10.49 (openwrt@aafbb23649f8) (gcc version 4.8.3 (OpenWrt/Linaro GCC 4.8-2014.04 r45620) ) #4 Fri Jun 5 10:49:14 UTC 2015
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 0.000000] MyLoader: sysp=444ba8b5, boardp=5fbcaeef, parts=ebc66edc
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] bootconsole [early0] enabled
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] CPU revision is: 00019374 (MIPS 24Kc)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] SoC: Atheros AR9330 rev 1
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] Clocks: CPU:400.000MHz, DDR:400.000MHz, AHB:200.000MHz, Ref:25.000MHz
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] Determined physical RAM map:
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] memory: 02000000 @ 00000000 (usable)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] Initrd not found or empty - disabling initrd
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.000000] Zone ranges:
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.000000] Normal [mem 0x00000000-0x01ffffff]
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.000000] Movable zone start for each node
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.000000] Early memory node ranges
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.000000] node 0: [mem 0x00000000-0x01ffffff]
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 0.000000] On node 0 totalpages: 8192
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 0.000000] free_area_init_node: node 0, pgdat 802aa5b0, node_mem_map 81000000
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 0.000000] Normal zone: 64 pages used for memmap
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 0.000000] Normal zone: 0 pages reserved
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 0.000000] Normal zone: 8192 pages, LIFO batch:0
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.000000] Primary instruction cache 64kB, VIPT, 4-way, linesize 32 bytes.
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.000000] Primary data cache 32kB, 4-way, VIPT, cache aliases, linesize 32 bytes
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 0.000000] pcpu-alloc: [0] 0
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 8128
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.000000] Kernel command line: board=TL-MR3020 console=ttyATH0,115200 rootfstype=squashfs,jffs2 noinitrd
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] PID hash table entries: 128 (order: -3, 512 bytes)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] Dentry cache hash table entries: 4096 (order: 2, 16384 bytes)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] Inode-cache hash table entries: 2048 (order: 1, 8192 bytes)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] Writing ErrCtl register=00000000
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] Readback ErrCtl register=00000000
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] Memory: 29168k/32768k available (2087k kernel code, 3600k reserved, 345k data, 252k init, 0k highmem)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.000000] NR_IRQS:51
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.080000] Calibrating delay loop... 265.42 BogoMIPS (lpj=1327104)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.080000] pid_max: default: 32768 minimum: 301
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.080000] Mount-cache hash table entries: 512
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.090000] NET: Registered protocol family 16
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.100000] MIPS: machine is TP-LINK TL-MR3020
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.350000] bio: create slab <bio-0> at 0
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.360000] Switching to clocksource MIPS
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.360000] NET: Registered protocol family 2
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.370000] TCP established hash table entries: 512 (order: 0, 4096 bytes)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.370000] TCP bind hash table entries: 512 (order: -1, 2048 bytes)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.370000] TCP: Hash tables configured (established 512 bind 512)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.380000] TCP: reno registered
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.380000] UDP hash table entries: 256 (order: 0, 4096 bytes)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.390000] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.400000] NET: Registered protocol family 1
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 0.400000] PCI: CLS 0 bytes, default 32
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.420000] squashfs: version 4.0 (2009/01/31) Phillip Lougher
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.420000] jffs2: version 2.2 (NAND) (SUMMARY) (LZMA) (RTIME) (CMODE_PRIORITY) (c) 2001-2006 Red Hat, Inc.
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.430000] msgmni has been set to 56
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.440000] io scheduler noop registered
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.440000] io scheduler deadline registered (default)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.450000] Serial: 8250/16550 driver, 1 ports, IRQ sharing disabled
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.450000] ar933x-uart: ttyATH0 at MMIO 0x18020000 (irq = 11) is a AR933X UART
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.460000] console [ttyATH0] enabled, bootconsole disabled
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.470000] ath79-spi ath79-spi: master is unqueued, this is deprecated
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.480000] m25p80 spi0.0: found s25sl032p, expected m25p80
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.480000] m25p80 spi0.0: s25sl032p (4096 Kbytes)
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.490000] 5 tp-link partitions found on MTD device spi0.0
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.490000] Creating 5 MTD partitions on "spi0.0":
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.500000] 0x000000000000-0x000000020000 : "u-boot"
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.510000] 0x000000020000-0x0000000fcedc : "kernel"
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.510000] mtd: partition "kernel" must either start or end on erase block boundary or be smaller than an erase block -- forcing read-only
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.520000] 0x0000000fcedc-0x0000003f0000 : "rootfs"
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 0.530000] mtd: partition "rootfs" must either start or end on erase block boundary or be smaller than an erase block -- forcing read-only
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.540000] mtd: device 2 (rootfs) set to be root filesystem
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.550000] 1 squashfs-split partitions found on MTD device rootfs
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.550000] 0x000000320000-0x0000003f0000 : "rootfs_data"
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.560000] 0x0000003f0000-0x000000400000 : "art"
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 0.560000] 0x000000020000-0x0000003f0000 : "firmware"
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 0.590000] libphy: ag71xx_mdio: probed
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 1.140000] ag71xx ag71xx.0: connected to PHY at ag71xx-mdio.1:04 [uid=004dd041, driver=Generic PHY]
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 1.150000] eth0: Atheros AG71xx at 0xb9000000, irq 4, mode:MII
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 1.150000] TCP: cubic registered
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 1.160000] NET: Registered protocol family 17
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 1.160000] 8021q: 802.1Q VLAN Support v1.8
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 1.170000] VFS: Mounted root (squashfs filesystem) readonly on device 31:2.
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 1.180000] Freeing unused kernel memory: 252K (802c1000 - 80300000)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.750000] usbcore: registered new interface driver usbfs
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.760000] usbcore: registered new interface driver hub
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.760000] usbcore: registered new device driver usb
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.770000] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.780000] ehci-platform: EHCI generic platform driver
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.780000] ehci-platform ehci-platform: EHCI Host Controller
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.790000] ehci-platform ehci-platform: new USB bus registered, assigned bus number 1
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.800000] ehci-platform ehci-platform: irq 3, io mem 0x1b000000
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.820000] ehci-platform ehci-platform: USB 2.0 started, EHCI 1.00
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.820000] hub 1-0:1.0: USB hub found
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.820000] hub 1-0:1.0: 1 port detected
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 3.830000] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 7.150000] eth0: link up (100Mbps/Full duplex)
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 7.630000] jffs2_scan_eraseblock(): End of filesystem marker found at 0x10000
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 7.640000] jffs2_build_filesystem(): unlocking the mtd device... done.
Fri Jun 5 10:48:36 2015 kern.warn kernel: [ 7.640000] jffs2_build_filesystem(): erasing all blocks after the end marker... done.
Fri Jun 5 10:48:36 2015 kern.notice kernel: [ 10.770000] jffs2: notice: (312) jffs2_build_xattr_subsystem: complete building xattr subsystem, 0 of xdatum (0 unchecked, 0 orphan) and 0 of xref (0 dead, 0 orphan) found.
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 11.490000] eth0: link down
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.010000] usbcore: registered new interface driver cdc_acm
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.010000] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.020000] Loading modules backported from Linux version master-2014-05-22-0-gf2032ea
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.030000] Backport generated by backports.git backports-20140320-37-g5c33da0
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.040000] nf_conntrack version 0.5.0 (459 buckets, 1836 max)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.060000] usbcore: registered new interface driver usbserial
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.070000] usbcore: registered new interface driver usbserial_generic
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.070000] usbserial: USB Serial support registered for generic
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.100000] xt_time: kernel timezone is -0000
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.140000] usbcore: registered new interface driver ftdi_sio
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.140000] usbserial: USB Serial support registered for FTDI USB Serial Device
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.150000] cfg80211: Calling CRDA to update world regulatory domain
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.160000] ip_tables: (C) 2000-2006 Netfilter Core Team
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.180000] cfg80211: World regulatory domain updated:
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.180000] cfg80211: DFS Master region: unset
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.180000] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.190000] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.200000] cfg80211: (2457000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.210000] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.220000] cfg80211: (5170000 KHz - 5250000 KHz @ 160000 KHz), (N/A, 2000 mBm), (N/A)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.230000] cfg80211: (5250000 KHz - 5330000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.230000] cfg80211: (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.240000] cfg80211: (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.250000] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 13.370000] ath: EEPROM regdomain: 0x0
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 13.370000] ath: EEPROM indicates default country code should be used
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 13.370000] ath: doing EEPROM country->regdmn map search
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 13.370000] ath: country maps to regdmn code: 0x3a
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 13.370000] ath: Country alpha2 being used: US
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 13.370000] ath: Regpair used: 0x3a
Fri Jun 5 10:48:36 2015 kern.debug kernel: [ 13.390000] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.400000] cfg80211: Calling CRDA for country: US
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.400000] cfg80211: Regulatory domain changed to country: US
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.410000] cfg80211: DFS Master region: FCC
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.410000] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.420000] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 3000 mBm), (N/A)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.430000] cfg80211: (5170000 KHz - 5250000 KHz @ 80000 KHz), (N/A, 1700 mBm), (N/A)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.440000] cfg80211: (5250000 KHz - 5330000 KHz @ 80000 KHz), (N/A, 2300 mBm), (0 s)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.450000] cfg80211: (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 3000 mBm), (N/A)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.450000] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 4000 mBm), (N/A)
Fri Jun 5 10:48:36 2015 kern.info kernel: [ 13.460000] ieee80211 phy0: Atheros AR9330 Rev:1 mem=0xb8100000, irq=2
Fri Jun 5 10:48:38 2015 daemon.err odhcpd[767]: Failed to open routing table: No such file or directory
Fri Jun 5 10:48:38 2015 daemon.err odhcpd[767]: Unable to open raw socket: Address family not supported by protocol
Fri Jun 5 10:48:39 2015 authpriv.info dropbear[796]: Not backgrounding
Fri Jun 5 10:48:42 2015 user.info autowifi: Invoking Doodle3D WiFi box network auto-initialization...
Fri Jun 5 10:48:42 2015 daemon.notice netifd: Interface 'lan' is enabled
Fri Jun 5 10:48:42 2015 daemon.notice netifd: Interface 'lan' is setting up now
Fri Jun 5 10:48:42 2015 kern.info kernel: [ 23.590000] device eth0 entered promiscuous mode
Fri Jun 5 10:48:42 2015 daemon.notice netifd: Interface 'lan' is now up
Fri Jun 5 10:48:42 2015 daemon.notice netifd: Interface 'loopback' is enabled
Fri Jun 5 10:48:42 2015 daemon.notice netifd: Interface 'loopback' is setting up now
Fri Jun 5 10:48:42 2015 daemon.notice netifd: Interface 'loopback' is now up
Fri Jun 5 10:48:42 2015 daemon.notice netifd: Network device 'lo' link is up
Fri Jun 5 10:48:42 2015 daemon.notice netifd: Interface 'loopback' has link connectivity
Fri Jun 5 10:48:43 2015 daemon.err odhcpd[868]: Failed to open routing table: No such file or directory
Fri Jun 5 10:48:43 2015 daemon.err odhcpd[868]: Unable to open raw socket: Address family not supported by protocol
Fri Jun 5 10:48:43 2015 kern.info kernel: [ 24.460000] eth0: link up (100Mbps/Full duplex)
Fri Jun 5 10:48:43 2015 user.notice firewall: Reloading firewall due to ifup of lan (br-lan)
Fri Jun 5 10:48:43 2015 kern.info kernel: [ 24.780000] br-lan: port 1(eth0) entered forwarding state
Fri Jun 5 10:48:43 2015 kern.info kernel: [ 24.780000] br-lan: port 1(eth0) entered forwarding state
Fri Jun 5 10:48:43 2015 daemon.notice netifd: Network device 'eth0' link is up
Fri Jun 5 10:48:43 2015 daemon.notice netifd: Bridge 'br-lan' link is up
Fri Jun 5 10:48:43 2015 daemon.notice netifd: Interface 'lan' has link connectivity
Fri Jun 5 10:48:44 2015 kern.info kernel: [ 24.960000] cfg80211: Calling CRDA for country: NL
Fri Jun 5 10:48:44 2015 kern.info kernel: [ 24.970000] cfg80211: Regulatory domain changed to country: NL
Fri Jun 5 10:48:44 2015 kern.info kernel: [ 24.970000] cfg80211: DFS Master region: ETSI
Fri Jun 5 10:48:44 2015 kern.info kernel: [ 24.980000] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
Fri Jun 5 10:48:44 2015 kern.info kernel: [ 24.990000] cfg80211: (2402000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
Fri Jun 5 10:48:44 2015 kern.info kernel: [ 25.000000] cfg80211: (5170000 KHz - 5250000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A)
Fri Jun 5 10:48:44 2015 kern.info kernel: [ 25.000000] cfg80211: (5250000 KHz - 5330000 KHz @ 80000 KHz), (N/A, 2000 mBm), (0 s)
Fri Jun 5 10:48:44 2015 kern.info kernel: [ 25.010000] cfg80211: (5490000 KHz - 5710000 KHz @ 80000 KHz), (N/A, 2700 mBm), (0 s)
Fri Jun 5 10:48:44 2015 kern.info kernel: [ 25.020000] cfg80211: (57240000 KHz - 65880000 KHz @ 2160000 KHz), (N/A, 4000 mBm), (N/A)
Fri Jun 5 10:48:45 2015 kern.info kernel: [ 26.780000] br-lan: port 1(eth0) entered forwarding state
Fri Jun 5 10:48:46 2015 daemon.notice netifd: Network device 'wlan0' link is up
Fri Jun 5 10:48:46 2015 daemon.notice netifd: Interface 'wlan' is enabled
Fri Jun 5 10:48:46 2015 daemon.notice netifd: Interface 'wlan' is setting up now
Fri Jun 5 10:48:46 2015 daemon.notice netifd: Interface 'wlan' is now up
Fri Jun 5 10:48:46 2015 daemon.notice netifd: Interface 'wlan' has link connectivity
Fri Jun 5 10:48:48 2015 daemon.info dnsmasq[1088]: started, version 2.71 cachesize 150
Fri Jun 5 10:48:48 2015 daemon.info dnsmasq[1088]: compile time options: no-IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP no-conntrack no-ipset no-auth no-DNSSEC
Fri Jun 5 10:48:48 2015 daemon.info dnsmasq-dhcp[1088]: DHCP, IP range 192.168.5.100 -- 192.168.5.249, lease time 12h
Fri Jun 5 10:48:48 2015 daemon.info dnsmasq[1088]: using local addresses only for domain lan
Fri Jun 5 10:48:48 2015 daemon.warn dnsmasq[1088]: no servers found in /tmp/resolv.conf.auto, will retry
Fri Jun 5 10:48:48 2015 daemon.info dnsmasq[1088]: read /etc/hosts - 1 addresses
Fri Jun 5 10:48:48 2015 daemon.info dnsmasq[1088]: read /tmp/hosts/dhcp - 1 addresses
Fri Jun 5 10:48:48 2015 daemon.info dnsmasq-dhcp[1088]: read /etc/ethers - 0 addresses
Fri Jun 5 10:48:48 2015 daemon.err odhcpd[1101]: Failed to open routing table: No such file or directory
Fri Jun 5 10:48:48 2015 daemon.err odhcpd[1101]: Unable to open raw socket: Address family not supported by protocol
Fri Jun 5 10:48:52 2015 daemon.info dnsmasq[1088]: exiting on receipt of SIGTERM
Fri Jun 5 10:48:52 2015 daemon.info dnsmasq[1155]: started, version 2.71 cachesize 150
Fri Jun 5 10:48:52 2015 daemon.info dnsmasq[1155]: compile time options: no-IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP no-conntrack no-ipset no-auth no-DNSSEC
Fri Jun 5 10:48:52 2015 daemon.info dnsmasq-dhcp[1155]: DHCP, IP range 192.168.10.100 -- 192.168.10.249, lease time 12h
Fri Jun 5 10:48:52 2015 daemon.info dnsmasq-dhcp[1155]: DHCP, IP range 192.168.5.100 -- 192.168.5.249, lease time 12h
Fri Jun 5 10:48:52 2015 daemon.info dnsmasq[1155]: using local addresses only for domain lan
Fri Jun 5 10:48:52 2015 daemon.warn dnsmasq[1155]: no servers found in /tmp/resolv.conf.auto, will retry
Fri Jun 5 10:48:52 2015 daemon.info dnsmasq[1155]: read /etc/hosts - 1 addresses
Fri Jun 5 10:48:52 2015 daemon.info dnsmasq[1155]: read /tmp/hosts/dhcp - 1 addresses
Fri Jun 5 10:48:52 2015 daemon.info dnsmasq-dhcp[1155]: read /etc/ethers - 0 addresses
Fri Jun 5 10:48:53 2015 daemon.err odhcpd[1215]: Failed to open routing table: No such file or directory
Fri Jun 5 10:48:53 2015 daemon.err odhcpd[1215]: Unable to open raw socket: Address family not supported by protocol
Fri Jun 5 10:48:56 2015 daemon.info dnsmasq-dhcp[1155]: DHCPDISCOVER(br-lan) c8:2a:14:02:a4:8a
Fri Jun 5 10:48:56 2015 daemon.info dnsmasq-dhcp[1155]: DHCPOFFER(br-lan) 192.168.5.220 c8:2a:14:02:a4:8a
Fri Jun 5 10:48:57 2015 daemon.info dnsmasq-dhcp[1155]: DHCPREQUEST(br-lan) 192.168.5.220 c8:2a:14:02:a4:8a
Fri Jun 5 10:48:57 2015 daemon.info dnsmasq-dhcp[1155]: DHCPACK(br-lan) 192.168.5.220 c8:2a:14:02:a4:8a peteruithoven
Fri Jun 5 10:48:58 2015 daemon.err odhcpd[1220]: Failed to open routing table: No such file or directory
Fri Jun 5 10:48:58 2015 daemon.err odhcpd[1220]: Unable to open raw socket: Address family not supported by protocol
Fri Jun 5 10:49:03 2015 daemon.err odhcpd[1225]: Failed to open routing table: No such file or directory
Fri Jun 5 10:49:03 2015 daemon.err odhcpd[1225]: Unable to open raw socket: Address family not supported by protocol
Fri Jun 5 10:49:03 2015 user.emerg syslog: Instance odhcpd::instance1 s in a crash loop 6 crashes, 0 seconds since last crash
Fri Jun 5 11:22:35 2015 authpriv.info dropbear[1261]: Child connection from 192.168.5.220:58196
Fri Jun 5 11:22:37 2015 authpriv.notice dropbear[1261]: Pubkey auth succeeded for 'root' with key md5 10:da:1c:13:91:2f:e3:da:f1:6e:93:f2:69:09:84:42 from 192.168.5.220:58196
It contains the Invoking Doodle3D WiFi box network auto-initialization...
log from the firmware's init script, but it doesn't include the Start signing in...
log. This could indicate that line /usr/share/lua/wifibox/script/d3dapi autowifi
fails.
From the wifibox (/tmp/wifibox.log
) the last interesting line is running in autowifi mode
I've been adding more logs in the lua code. When it fails it seems to fail on the iwinfo
's device scanlist
method. Of the following code, logging ends with deviceApi: nl80211
. So somehow it aborts, without any errors.
log:info(" deviceApi: " .. (deviceApi or "<nil>"))
local iw = iwinfo[deviceApi]
local sr = iw.scanlist(deviceName)
log:info(" scan done")
I found the following OpenWRT issues around iwinfo.scanlist()
:
- https://dev.openwrt.org/ticket/8406
- https://dev.openwrt.org/ticket/17256
I can find the changes from the mentioned fix in the version we use (14.07).
For the REST API we normally use pcall, this calls a api specific module in protected mode. It does this unless confDefaults.DEBUG_PCALLS
is set to true.
if confDefaults.DEBUG_PCALLS then ok, modObj = true, require(reqModName)
else ok, modObj = pcall(require, reqModName)
Maybe I can use this logic to get more info from the setupAutoWifiMode
function.
Running setupAutoWifiMode
using pcall()
doesn't help, no logs.
Logread contains the following a couple of times, not sure if that indicates something relevant.
Fri Jun 5 12:54:39 2015 daemon.err odhcpd[811]: Failed to open routing table: No such file or directory
Fri Jun 5 12:54:39 2015 daemon.err odhcpd[811]: Unable to open raw socket: Address family not supported by protocol
Not sure how to continue...
Running setupAutoWifiMode
using pcall()
doesn't help, no logs.
Logread contains the following a couple of times, not sure if that indicates something relevant.
Fri Jun 5 12:54:39 2015 daemon.err odhcpd[811]: Failed to open routing table: No such file or directory
Fri Jun 5 12:54:39 2015 daemon.err odhcpd[811]: Unable to open raw socket: Address family not supported by protocol
I've written a very simple lua script to just test scanlist.
local iwinfo = require('iwinfo')
print("calling scanlist")
local scanList = iwinfo.nl80211.scanlist("wlan0")
print("scanlist completed")
print("scanlist:")
for _,sn in ipairs(scanList) do
print(" - " .. (sn.ssid or "<nil>"))
end
It executes on boot before the firmware code by adding the following to the init script.
$LOGGER "Invoking scan..."
lua /root/scan.lua 1> /tmp/scan.log 2>&1
$LOGGER "Scan complete"
Then I can see in logread that it sticks at Invoking scan...,
But, nothing shows up in /tmp/scan.log. When I manually call ua /root/scan.lua 1> /tmp/scan.log 2>&1
a list does appear in scan.log.
Not sure what's going on...
I also noticed that when I call this script, it does finish booting somehow (the big button stops flashing). Almost like this extra scanlist
request influences the first.
After removing the scanlist call the scan.log file is populated. So maybe the script needs to finish in order for logs to be written.
Experiment to write the logs to a log from lua:
local io = require('io')
local file = assert(io.open('/tmp/scan.log', "w"))
function logger(message)
print(message)
file:write(message .. "\n")
file:flush()
end
logger("init")
local iwinfo = require('iwinfo')
logger("calling scanlist")
local scanList = iwinfo.nl80211.scanlist("wlan0")
logger("scanlist completed")
logger("scanlist:")
for _,sn in ipairs(scanList) do
logger(" - " .. (sn.ssid or "<nil>"))
end
This results in logs, which end with calling scanlist
. It's almost like scanlist
doesn't finish when called during boot.
Isn't there a timeout? Could we add a timeout?
Checked init scripts order, seems okay:
# ls -l /etc/rc*.d
lrwxrwxrwx 1 root root 18 Jun 5 12:00 K50dropbear -> ../init.d/dropbear
lrwxrwxrwx 1 root root 16 Jun 5 12:00 K85odhcpd -> ../init.d/odhcpd
lrwxrwxrwx 1 root root 13 Jun 5 12:00 K89log -> ../init.d/log
lrwxrwxrwx 1 root root 17 Jun 5 12:00 K90network -> ../init.d/network
lrwxrwxrwx 1 root root 14 Jun 5 12:00 K98boot -> ../init.d/boot
lrwxrwxrwx 1 root root 16 Jun 5 12:00 K99umount -> ../init.d/umount
lrwxrwxrwx 1 root root 20 Jun 5 12:00 S00sysfixtime -> ../init.d/sysfixtime
lrwxrwxrwx 1 root root 14 Jun 5 12:00 S10boot -> ../init.d/boot
lrwxrwxrwx 1 root root 16 Jun 5 12:00 S10system -> ../init.d/system
lrwxrwxrwx 1 root root 16 Jun 5 12:00 S11sysctl -> ../init.d/sysctl
lrwxrwxrwx 1 root root 13 Jun 5 12:00 S12log -> ../init.d/log
lrwxrwxrwx 1 root root 18 Jun 5 12:00 S19firewall -> ../init.d/firewall
lrwxrwxrwx 1 root root 17 Jun 5 12:00 S20network -> ../init.d/network
lrwxrwxrwx 1 root root 16 Jun 5 12:00 S35odhcpd -> ../init.d/odhcpd
lrwxrwxrwx 1 root root 14 Jun 5 12:00 S50cron -> ../init.d/cron
lrwxrwxrwx 1 root root 18 Jun 5 12:00 S50dropbear -> ../init.d/dropbear
lrwxrwxrwx 1 root root 16 Jun 5 12:00 S50telnet -> ../init.d/telnet
lrwxrwxrwx 1 root root 16 Jun 5 12:00 S50uhttpd -> ../init.d/uhttpd
lrwxrwxrwx 1 root root 17 Jun 5 12:00 S60dnsmasq -> ../init.d/dnsmasq
lrwxrwxrwx 1 root root 17 Jun 5 12:00 S61wifibox -> ../init.d/wifibox
lrwxrwxrwx 1 root root 14 Jun 5 12:00 S95done -> ../init.d/done
lrwxrwxrwx 1 root root 13 Jun 5 12:00 S96led -> ../init.d/led
lrwxrwxrwx 1 root root 17 Jun 5 12:00 S98sysntpd -> ../init.d/sysntpd
lrwxrwxrwx 1 root root 19 Jun 5 12:00 S99dhcpcheck -> ../init.d/dhcpcheck
lrwxrwxrwx 1 root root 17 Jun 5 12:00 S99print3d -> ../init.d/print3d
I was hoping I could add more checks, but I'm having a hard time retrieving network related info.
I've added more checks to Lua, but they don't report any issues.
local iwinfo = require('iwinfo')
local deviceName = 'wlan0'
local deviceID = iwinfo.type(deviceName)
if not deviceID then
logger("wireless device '" .. deviceName .. "' not found")
else
logger("found wireless device '" .. deviceName .. "'")
end
local wifiDevice = iwinfo[deviceID]
if not wifiDevice then
logger("'iwinfo." .. deviceID .. "' interface not found")
else
logger("found 'iwinfo." .. deviceID .. "' interface")
end
I can check /proc/net/dev
, this seems to list network devices and some info. This is what it lists on boot:
Inter-| Receive | Transmit
face |bytes packets errs drop fifo frame compressed multicast|bytes packets errs drop fifo colls carrier compressed
lo: 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
wlan0: 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
eth0: 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
After boot it lists:
Inter-| Receive | Transmit
face |bytes packets errs drop fifo frame compressed multicast|bytes packets errs drop fifo colls carrier compressed
lo: 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
wlan0: 0 0 0 0 0 0 0 0 360 1 0 0 0 0 0 0
eth0: 25175 169 0 0 0 0 0 0 13108 87 0 0 0 0 0 0
br-lan: 22717 167 0 13 0 0 0 0 13016 85 0 0 0 0 0 0
The following Lua Network utility also checks /proc/net/dev
.
https://github.com/LeftyBC/awesome/blob/master/delightful/widgets/network.lua
So I could check whether wlan0 transmitted more than 0 packets, but this feels like quite a hack. There has to be more info somewhere.
/proc/net/wireless
doesn't seem to change.
What simply calling the iwinfo cli returns might be interesting.
During boot:
wlan0 ESSID: unknown
Access Point: 00:00:00:00:00:00
Mode: Client Channel: unknown (unknown)
Tx-Power: 0 dBm Link Quality: unknown/70
Signal: unknown Noise: unknown
Bit Rate: unknown
Encryption: unknown
Type: nl80211 HW Mode(s): 802.11bgn
Hardware: unknown [Generic MAC80211]
TX power offset: unknown
Frequency offset: unknown
Supports VAPs: yes PHY name: phy0
After boot:
wlan0 ESSID: "Doodle3D-4CCE92"
Access Point: 10:FE:ED:4C:CE:92
Mode: Master Channel: 11 (2.462 GHz)
Tx-Power: 15 dBm Link Quality: unknown/70
Signal: unknown Noise: -94 dBm
Bit Rate: unknown
Encryption: none
Type: nl80211 HW Mode(s): 802.11bgn
Hardware: unknown [Generic MAC80211]
TX power offset: unknown
Frequency offset: unknown
Supports VAPs: yes PHY name: phy0
Logging iw event since boot (before calling our scan script) gives:
1433511598.748261: wlan0 (phy #0): scan aborted: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462,
1433511599.037800: regulatory domain change: set to NL by a user request
Maybe this regulatory domain change cancels the scan?
We do this in our post-install.sh script, could this be running on boot somehow?
https://github.com/Doodle3D/doodle3d-firmware/blob/master/post-install.sh#L80
Adding a 5s sleep before starting scanning seems to avoid the issue.
iw events (which I start before this sleep), now outputs:
1433520179.262326: regulatory domain change: set to NL by a user request
1433520181.324454: wlan0 (phy #0): scan started
1433520182.751965: wlan0 (phy #0): scan finished: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472,
1433520183.957474: wlan0 (phy #0): scan started
1433520185.392125: wlan0 (phy #0): scan finished: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472,
1433522832.289685: wlan0 (phy #0): mgmt TX status (cookie 80c7fd80): acked
1433522832.297195: wlan0 (phy #0): mgmt TX status (cookie 80c96840): acked
1433522832.299991: wlan0: new station b8:e8:56:2e:a1:96
1433522852.640755: wlan0 (phy #0): mgmt TX status (cookie 80c7f540): acked
1433522852.645812: wlan0 (phy #0): mgmt TX status (cookie 80c7f900): acked
1433522852.664555: wlan0 (phy #0): mgmt TX status (cookie 80c7f540): acked
1433522852.707280: wlan0 (phy #0): mgmt TX status (cookie 80c7f000): acked
1433522855.326191: wlan0 (phy #0): mgmt TX status (cookie 80c7f180): acked
1433522855.350708: wlan0 (phy #0): mgmt TX status (cookie 80c7f900): acked
1433522855.420976: wlan0 (phy #0): mgmt TX status (cookie 80ca3cc0): no ack
1433522855.764757: wlan0 (phy #0): mgmt TX status (cookie 80c7e900): acked
1433522855.854832: wlan0 (phy #0): mgmt TX status (cookie 80c7e900): acked
1433522975.335233: wlan0: del station b8:e8:56:2e:a1:96
1433522976.347087: wlan0 (phy #0): mgmt TX status (cookie 80c969c0): no ack
There doesn't seem to be support for getting the iw events in the lua binding, and I don't really want to read logread from lua. Also checking specifically for country changes seems very very fragile, even more fragile than a timeout.
I'm hoping I can abort scanlist after a timeout, then I can have it attempt a scan 3 times with a 2 seconds timeout. Than it can handle all sorts of issues while not taking extra time when there are no issues.
Hopefully I can create timeouts in Lua...
So far I know it's not easy to add a timeout. Some things like the LuaSocket library, which enables you to do HTTP requests, has a setTimeout function which can make certain calls non blocking. See: http://www.lua.org/pil/9.4.html
In general I'd like to reach out to the iw / iwinfo (or the lua binding) maintainers, but the only info I can find is:
- The source: http://git.openwrt.org/?p=project/iwinfo.git;a=blob;f=iwinfo_lua.c;h=1a9100123940a73fc6dabf3a5380e9c4b762bc4e;hb=HEAD
- A Wireless utility wiki page: http://wiki.openwrt.org/doc/howto/wireless.utilities
- Wi's wiki page (which probably isn't the version we use, it doesn't include lua bindings for example): https://wireless.wiki.kernel.org/en/users/Documentation/iw
I'm probably spoiled with github, but where is the issue queue? I probably have to find the right mailinglist.
I did find a way to start something in a non blocking way in lua, though popen:
logger("starting scanner")
local scannerHandler = io.popen("lua ./scanner.lua")
logger("started scanner")
See below the interesting parts from logread, looks like we need at least a delay of 4 seconds.
Fri Jun 5 17:13:48 2015 user.info autowifi: Doodle3D firmware init
Fri Jun 5 17:13:50 2015 kern.info kernel: [ 19.990000] cfg80211: Regulatory domain changed to country: NL
Fri Jun 5 17:13:52 2015 daemon.notice netifd: Interface 'wlan' is now up
The io.popen
trick won't work, because the read function (the function you use to read the output) is blocking.
Looking into coroutines now.
Since the scanlist method can't be put into a non blocking mode, the following module might be interesting.
https://github.com/Tieske/corowatch/blob/master/src/corowatch.lua
Also interesting; it's published with LuaRocks.
We've checked what happens when we remove our custom country (NL) and channel (11?) configuration.
In the logread I see the country code isn't changed again, it's just set to the default. Our original 1 second delay is enough and the scan completes successfully.
These uci wireless settings are set by the post-install.sh of doodle3d-firmware.
When I remove the change to NL scanning still fails, but when I also explicitly remove the channel scanning works.
This does mean we'll be using channel 1 instead of 11, this might influence the the wifi connection people have with the WiFi-Box. We'll try to test this.
Increasing the timeout before starting our wifibox code seems to fix this. For a better solution see: #32
Someone on the OpenWRT mailinglist, responded to my scanlist issue with:
I suspect the culprit is nl80211_wait() which calls nl_recvmsgs()
internally.
To overcome this problem we need to restructure the nl80211 code to use
nonblocking sockets and then extend the nl80211_wait() implementation to
have a timeout.
Also from mailinglist:
ok...then you can maybe with hotplug wait for ACTION='ifup'
maybe something like this (will not work, but you get the idea)
#!/bin/sh
# hotplug-script:
SCANNED='/your/path'
MYCHANNELS='1 2 3 154 168'
[ "$ACTION" = 'ifup' -a -e "$SCANNED" ] && {
scan_for_known_networks | while read NETWORK_SETTINGS ; do
connect $NETWORK_SETTINGS # ssid, channel, pass etc.
rm $SCANNED
done
}
[ "$ACTION" = 'ifup' -a "$INTERFACE" = 'mywifi' ] && {
for CHAN in $MYCHANNELS; do
create_adhoc $CHAN
touch 'SCANNED'
wifi
done
}