Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

stuck while rebooting when driver is loaded? #36

Closed
mpvader opened this issue Sep 16, 2016 · 12 comments
Closed

stuck while rebooting when driver is loaded? #36

mpvader opened this issue Sep 16, 2016 · 12 comments

Comments

@mpvader
Copy link

mpvader commented Sep 16, 2016

Hi,

with the rtl8723bu driver loaded, my device won't reboot anymore. Its 100% reproducible. And solved by booting without loading the driver.

system log output is:

root@beaglebone:~# reboot

Broadcast message from root@beaglebone (ttyO0) (Fri Sep 16 00:00:49 2016):
The system is going down for reboot NOW!
INIT: Sending processes the TERM signal
root@beaglebone:~#
INIT: Sending processes the KILL signal
Stopping simple-upnpd
Stopping system message bus
hwclock: can't open '/dev/misc/rtc': No such file or directory
Stopping syslogd/klogd: stopped syslogd (pid 1842)
stopped klogd (pid 1843)
done
Stopping Connection Manager
[  325.401405] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Stopping crond: OK
Gracefully shutting down php-fpm . done
Stopping Hiawatha Web Server: stopped /usr/sbin/hiawatha (pid 1967)
hiawatha.
Deconfiguring network interfaces... done.
Sending all processes the TERM signal...
[  328.963540] RTL871X: nolinked power save enter
Sending all processes the KILL signal...
Unmounting remote filesystems...
Deactivating swap...
Unmounting local filesystems...
[  333.493695] EXT4-fs (mmcblk1p3): re-mounted. Opts: data=ordered
Rebooting... [  335.629452] musb-hdrc musb-hdrc.1.auto: remove, state 1
[  335.635012] usb usb1: USB disconnect, device number 1
[  335.640312] usb 1-1: USB disconnect, device number 2
[  335.645536] usb 1-1.4: USB disconnect, device number 3

the used device is a beaglebone enhanced from Sancloud, running our own image called Venus. So not the IoT beaglebone image. I am still awaiting feedback to know if this same issue happens on their beaglebone IoT image, as I know they use this same driver.

Any ideas? Is this a known issue?

Matthijs

ps. I have this issue (also) when not working with the concurrent_mode. About which I made that other issue for last night, #35. So thought it best to keep these two issues seperate. Also I have some more compile errors with the concurrent_mode. And fixes for them this time ;-). I'll post that in #35, after doing some more tests.

@sancloud
Copy link

The board hangs when rebooting with the IoT 8.4 image, don't know exactly what is causing it yet:
root@beaglebone:~# reboot
Starting Synchronise Hardware Clock to System Clock...
[ OK ] Stopped target System Time Synchronized.
[ OK ] Stopped Update UTMP about System Runlevel Changes.
[ OK ] Stopped target Graphical Interface.
Stopping Entropy daemon using the HAVEGE algorithm...
[ OK ] Stopped target Multi-User System.
Stopping System Logging Service...
Stopping Bonescript autorun...
Stopping Regular background program processing daemon...
Stopping OpenBSD Secure Shell server...
Stopping Avahi mDNS/DNS-SD Stack...
Stopping Login Service...
[ OK ] Stopped target Login Prompts.
Stopping Serial Getty on ttyGS0...
Stopping Getty on tty1...
Stopping Serial Getty on ttyS0..[ OK ] Stopped LSB: Advanced IEEE 802.11 management daemon.
Stopping LSB: set CPUFreq kernel parameters...
[ OK ] Stopped LSB: Apache2 web server.
[ OK ] Stopped target Network is Online.
Stopping Wait for network to be configured by ConnMan...
Stopping LSB: Start busybox udhcpd at boot time...
[ OK ] Stopped target Bluetooth.
Stopping Bluetooth service...
Starting Store Sound Card State...
[ OK ] Stopped Entropy daemon using the HAVEGE algorithm.
[ OK ] Stopped Bonescript autorun.
[ OK ] Stopped Regular background program processing daemon.
[ OK ] Stopped Login Service.
[ OK ] Stopped Avahi mDNS/DNS-SD Stack.
[ OK ] Stopped System Logging Service.
[ OK ] Stopped Wait for network to be configured by ConnMan.
[ OK ] Stopped Getty on tty1.
[ OK ] Stopped Serial Getty on ttyS0.
[ OK ] Stopped Bluetooth service.
[ OK ] Stopped OpenBSD Secure Shell server.
[ OK ] Stopped Serial Getty on ttyGS0.
[ OK ] Stopped LSB: set CPUFreq kernel parameters.
[ OK ] Stopped LSB: Start busybox udhcpd at boot time.
[FAILED] Failed to start Store Sound Card State.
See 'systemctl status alsa-store.service' for details.
Stopping LSB: Load kernel modules needed to enable cpufreq scaling...
[ OK ] Removed slice system-serial\x2dgetty.slice.
[ OK ] Removed slice system-getty.slice.
Stopping /etc/rc.local Compatibility...
[ OK ] Stopped /etc/rc.local Compatibility.
[ OK ] Stopped target Network.
Stopping WPA supplicant...
Stopping Permit User Sessions...
Stopping Connection service...
[ OK ] Started Synchronise Hardware Clock to System Clock.
[ OK ] Stopped WPA supplicant.
[ OK ] Stopped LSB: Load kernel modules needed to enable cpufreq scaling.
[ OK ] Stopped Permit User Sessions.
[ OK ] Stopped Connection service.
Stopping D-Bus System Message Bus...
[ OK ] Stopped target Remote File Systems.
[ OK ] Stopped target Remote File Systems (Pre).
[ OK ] Stopped D-Bus System Message Bus.
[ OK ] Stopped target Basic System.
[ OK ] Stopped target Slices.
[ OK ] Removed slice User and Session Slice.
[ OK ] Stopped target Paths.
[ OK ] Stopped target Timers.
[ OK ] Stopped target Sockets.
[ OK ] Closed node-red.socket.
[ OK ] Closed cloud9.socket.
[ OK ] Closed bonescript.socket.
[ OK ] Closed Syslog Socket.
[ OK ] Closed Avahi mDNS/DNS-SD Stack Activation Socket.
[ OK ] Closed D-Bus System Message Bus Socket.
[ OK ] Stopped target System Initialization.
Stopping Load/Save RF Kill Switch Status of rfkill1...
Stopping Load/Save RF Kill Switch Status of rfkill0...
Stopping Network Time Synchronization...
Stopping Apply Kernel Variables...
[ OK ] Stopped Apply Kernel Variables.
Stopping Load Kernel Modules...
[ OK ] Stopped Load Kernel Modules.
Stopping Update UTMP about System Boot/Shutdown...
[ OK ] Stopped target Encrypted Volumes.
Stopping LSB: Raise network interfaces....
[ OK ] Stopped target Swap.
[ OK ] Stopped Network Time Synchronization.
[ OK ] Stopped Load/Save RF Kill Switch Status of rfkill1.
[ OK ] Stopped Load/Save RF Kill Switch Status of rfkill0.
[ OK ] Stopped Update UTMP about System Boot/Shutdown.
[ OK ] Stopped LSB: Raise network interfaces..
Stopping Load/Save Random Seed...
[ OK ] Removed slice system-systemd\x2drfkill.slice.
Stopping Create Volatile Files and Directories...
[ OK ] Stopped Create Volatile Files and Directories.
[ OK ] Stopped target Local File Systems.
Unmounting /sys/kernel/debug...
[ OK ] Stopped Load/Save Random Seed.
[ OK ] Unmounted /sys/kernel/debug.
[ OK ] Reached target Unmount All Filesystems.
[ OK ] Stopped target Local File Systems (Pre).
Stopping Create Static Device Nodes in /dev...
[ OK ] Stopped Create Static Device Nodes in /dev.
Stopping Remount Root and Kernel File Systems...
[ OK ] Stopped Remount Root and Kernel File Systems.
[ OK ] Reached target Shutdown.
[ OK ] Reached target Final Step.
Starting Reboot...
[ 101.974320] watchdog watchdog0: watchdog did not stop!

@lwfinger
Copy link
Owner

Unfortunately, your logs do not show anything about what is happening. I'm not that familiar with any of the special boot operations for Beaglebone and similar devices. Is it possible to get any boot details?

@RobertCNelson
Copy link

@lwfinger nothing really special, it's ti's v4.4.x branch, with a debian-ish kitchen sink config:

https://github.com/RobertCNelson/ti-linux-kernel-dev/blob/ti-linux-4.4.y/patches/defconfig

We build rtl8723bu with the default settings and package up 8723bu.ko into a deb package.

https://github.com/rcn-ee/rtl8723bu/blob/master/build.sh#L9

My SanCloud variant is at work, so i can't test this on other kernel's till monday.

Regards,

mpvader added a commit to victronenergy/meta-victronenergy that referenced this issue Sep 18, 2016
Make sure to add this commit from upstream in the openembedded-core mete:
openembedded/openembedded-core@afcea61

Itś needed to prevent these errors during compile:
WARNING: "wiphy_free" [/media/venusbuilds/wipbbbjethro/build/tmp-glibc/work/beaglebone-ve-linux-gnueabi/rtl8723bu/0.0-r0/git/8723bu.ko] undefined!
WARNING: "cfg80211_unlink_bss" [/media/venusbuilds/wipbbbjethro/build/tmp-glibc/work/beaglebone-ve-linux-gnueabi/rtl8723bu/0.0-r0/git/8723bu.ko] undefined!
[many more]

and later, when using the ko file, there errors in the bootlog:
[    4.554499] 8723bu: no symbol version for cfg80211_scan_done
[    4.560468] 8723bu: Unknown symbol cfg80211_scan_done (err -22)
...
many more, resulting in module not loading unless doing a manual modprobe -f

OPEN ISSUES
0) I added lib80211 to the defconfig at some point while trying to fix above
   issue. Probably isn't needed anymore. Todo: test & remove

1) Replace the hack in the rtl8723bu Makefile with something proper

2) Reboot doesn't work
   lwfinger/rtl8723bu#36

3) Kernel deadlocks right after boot:
[...]
[    3.544110] udevd[677]: starting version 182
[    4.125070] cfg80211: Calling CRDA to update world regulatory domain
[    4.499920] RTL871X: module init start
[    4.503973] RTL871X: rtl8723bu v4.3.6.11_12942.20141204_BTCOEX20140507-4E40
[    4.511273] RTL871X: rtl8723bu BT-Coex version = BTCOEX20140507-4E40
[    7.276123] cfg80211: Calling CRDA to update world regulatory domain
[    7.816563] RTL871X: rtw_ndev_init(wlan0)
[    7.823760] usbcore: registered new interface driver rtl8723bu
[    7.829887] RTL871X: module init ret=0
[    8.275916] EXT4-fs (mmcblk1p3): re-mounted. Opts: data=ordered
bootlogd: cannot allocate pseudo tty: No such file or directory
[    8.419817] random: dd urandom read with 105 bits of entropy available
Populating dev cache
[   10.432973] cfg80211: Calling CRDA to update world regulatory domain
hwclock: can't open '/dev/misc/rtc': No such file or directory
Thu Sep 15 23:48:31 UTC 2016
hwclock: can't open '/dev/misc/rtc': No such file or directory
Starting watchdog
[   11.915814] watchdog watchdog0: watchdog did not stop!
[   13.582859] cfg80211: Calling CRDA to update world regulatory domain
[   14.169740] random: nonblocking pool is initialized
update-rc.d: /etc/init.d/run-postinsts exists during rc.d purge (continuing)
 Removing any system startup links for run-postinsts ...
  /etc/rcS.d/S99run-postinsts
INIT: Entering runlevel: 5
Configuring network interfaces... [   14.520549] net eth0: initializing cpsw version 1.12 (0)
[   14.603248] net eth0: phy found : id is : 0x4dd072
[   14.608427] libphy: PHY 4a101000.mdio:01 not found
[   14.613487] net eth0: phy 4a101000.mdio:01 not found on slave 1
[   14.625689] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
udhcpc (v1.23.2) started
Sending discover...
[   16.732824] cfg80211: Calling CRDA to update world regulatory domain
Sending discover...
[   19.882724] cfg80211: Calling CRDA to update world regulatory domain
Sending discover...
[   23.032729] cfg80211: Calling CRDA to update world regulatory domain
No lease, forking to background
[   23.865391] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
done.
Starting system message bus: Setting up watches.
Watches established.
/var/run/dbus/ CREATE system_bus_socket
hwclock: can't open '/dev/misc/rtc': No such file or directory
Starting syslogd/klogd: done
Starting php-fpm [   25.190096] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   25.197402] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   25.991495] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   25.998758] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   26.182841] cfg80211: Calling CRDA to update world regulatory domain
 done
Starting Connection Manager
Starting Hiawatha Web Server: [   26.981252] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   26.988575] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
hiawatha.
dbus[1832]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
Starting crond: dbus[1832]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
OK
[   27.518031]
[   27.519624] =============================================
[   27.525281] [ INFO: possible recursive locking detected ]
[   27.530944] 4.1.15-venus #1 Tainted: G           O
[   27.536236] ---------------------------------------------
[   27.541892] connmand/1959 is trying to acquire lock:
[   27.547094]  (pmutex){+.+...}, at: [<bf0ef664>] usbctrl_vendorreq+0x7c/0x274 [8723bu]
[   27.555649]
[   27.555649] but task is already holding lock:
[   27.561764]  (pmutex){+.+...}, at: [<bf0ee454>] netdev_open+0x28/0x50 [8723bu]
[   27.569468]
[   27.569468] other info that might help us debug this:
[   27.576311]  Possible unsafe locking scenario:
[   27.576311]
[   27.582516]        CPU0
[   27.585075]        ----
[   27.587632]   lock(pmutex);
[   27.590565]   lock(pmutex);
[   27.593497]
[   27.593497]  *** DEADLOCK ***
[   27.593497]
[   27.599704]  May be due to missing lock nesting notation
[   27.599704]
[   27.606822] 2 locks held by connmand/1959:
[   27.611111]  #0:  (rtnl_mutex){+.+.+.}, at: [<c042d050>] devinet_ioctl+0xd0/0x7d4
[   27.618996]  #1:  (pmutex){+.+...}, at: [<bf0ee454>] netdev_open+0x28/0x50 [8723bu]
[   27.627136]
[   27.627136] stack backtrace:
[   27.631706] CPU: 0 PID: 1959 Comm: connmand Tainted: G           O    4.1.15-venus #1
[   27.639914] Hardware name: Generic AM33XX (Flattened Device Tree)
[   27.646326] [<c0014844>] (unwind_backtrace) from [<c0012994>] (show_stack+0x10/0x14)
[   27.654455] [<c0012994>] (show_stack) from [<c0067fe0>] (__lock_acquire+0x1454/0x1da0)
[   27.662759] [<c0067fe0>] (__lock_acquire) from [<c006922c>] (lock_acquire+0xac/0x12c)
[   27.670979] [<c006922c>] (lock_acquire) from [<c04bffd4>] (mutex_lock_interruptible_nested+0x48/0x3bc)
[   27.680833] [<c04bffd4>] (mutex_lock_interruptible_nested) from [<bf0ef664>] (usbctrl_vendorreq+0x7c/0x274 [8723bu])
[   27.692079] [<bf0ef664>] (usbctrl_vendorreq [8723bu]) from [<bf11e9f0>] (usb_read8+0x30/0x3c [8723bu])
[   27.702011] [<bf11e9f0>] (usb_read8 [8723bu]) from [<bf0c1178>] (rtw_read8+0x18/0x1c [8723bu])
[   27.711204] [<bf0c1178>] (rtw_read8 [8723bu]) from [<bf11ceb0>] (rtl8723bu_hal_init+0x30/0xb4c [8723bu])
[   27.721338] [<bf11ceb0>] (rtl8723bu_hal_init [8723bu]) from [<bf1026b4>] (rtw_hal_init+0x18/0x154 [8723bu])
[   27.731727] [<bf1026b4>] (rtw_hal_init [8723bu]) from [<bf0ee20c>] (_netdev_open+0x64/0x284 [8723bu])
[   27.741561] [<bf0ee20c>] (_netdev_open [8723bu]) from [<bf0ee45c>] (netdev_open+0x30/0x50 [8723bu])
[   27.751143] [<bf0ee45c>] (netdev_open [8723bu]) from [<c03c8884>] (__dev_open+0xb8/0x11c)
[   27.759726] [<c03c8884>] (__dev_open) from [<c03c8b08>] (__dev_change_flags+0x94/0x144)
[   27.768123] [<c03c8b08>] (__dev_change_flags) from [<c03c8bd0>] (dev_change_flags+0x18/0x48)
[   27.776978] [<c03c8bd0>] (dev_change_flags) from [<c042d64c>] (devinet_ioctl+0x6cc/0x7d4)
[   27.785559] [<c042d64c>] (devinet_ioctl) from [<c03ae70c>] (sock_ioctl+0x1d8/0x2b0)
[   27.793593] [<c03ae70c>] (sock_ioctl) from [<c011c39c>] (do_vfs_ioctl+0x3f0/0x5c0)
[   27.801533] [<c011c39c>] (do_vfs_ioctl) from [<c011c5a0>] (SyS_ioctl+0x34/0x5c)
[   27.809201] [<c011c5a0>] (SyS_ioctl) from [<c000f1e0>] (ret_fast_syscall+0x0/0x54)
Checking available software versions...
[   28.191668] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
Starting simple-upnpd
[   31.095134] RTL871X: RTW_ADAPTIVITY_EN_AUTO, chplan:0x20, Regulation:0,0
[   31.102220] RTL871X: RTW_ADAPTIVITY_MODE_NORMAL
[   32.523712] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   32.536569] cfg80211: Calling CRDA to update world regulatory domain
[   32.604106] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   32.611164] c_can_platform 481d0000.can: obtain a copy of previously claimed pinctrl
[   32.619469] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   33.212819] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   33.220096] c_can_platform 481d0000.can: obtain a copy of previously claimed pinctrl
[   33.291001] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   33.704635] RTL871X: nolinked power save enter
[   39.083257] RTL871X: RTW_ADAPTIVITY_EN_AUTO, chplan:0x20, Regulation:0,0
[   39.090326] RTL871X: RTW_ADAPTIVITY_MODE_NORMAL
[   40.204562] RTL871X: nolinked power save leave
[   40.425420] RTL871X: rtw_set_802_11_connect(wlan0)  fw_state=0x00000008
[   40.432584] cfg80211: Calling CRDA to update world regulatory domain
[   40.498385] RTL871X: start auth
[   40.503755] RTL871X: auth success, start assoc
[   40.512793] RTL871X: rtw_cfg80211_indicate_connect(wlan0) BSS not found !!
[   40.520058] RTL871X: assoc success
[   40.524101] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   40.956425] RTL871X: send eapol packet
[   40.978771] RTL871X: send eapol packet
[   40.994451] RTL871X: set pairwise key camid:4, addr:98:fc:11:ae:b5:04, kid:0, type:AES
bgscan simple: Failed to enable signal strength monitoring
[   41.024333] RTL871X: set group key camid:5, addr:98:fc:11:ae:b5:04, kid:1, type:AES
[   43.582737] cfg80211: Calling CRDA to update world regulatory domain
[   46.732739] cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
mpvader added a commit to victronenergy/meta-victronenergy that referenced this issue Sep 19, 2016
Make sure to add this commit from upstream in the openembedded-core mete:
openembedded/openembedded-core@afcea61

It's needed to prevent these errors during compile:
WARNING: "wiphy_free" [/media/venusbuilds/wipbbbjethro/build/tmp-glibc/work/beaglebone-ve-linux-gnueabi/rtl8723bu/0.0-r0/git/8723bu.ko] undefined!
WARNING: "cfg80211_unlink_bss" [/media/venusbuilds/wipbbbjethro/build/tmp-glibc/work/beaglebone-ve-linux-gnueabi/rtl8723bu/0.0-r0/git/8723bu.ko] undefined!
[many more]

and later, when using the ko file, there errors in the bootlog:
[    4.554499] 8723bu: no symbol version for cfg80211_scan_done
[    4.560468] 8723bu: Unknown symbol cfg80211_scan_done (err -22)
...
many more, resulting in module not loading unless doing a manual modprobe -f

OPEN ISSUES
0) I added lib80211 to the defconfig at some point while trying to fix above
   issue. Probably isn't needed anymore. Todo: test & remove

1) Replace the hack in the rtl8723bu Makefile with something proper

2) Reboot doesn't work
   lwfinger/rtl8723bu#36

3) Kernel deadlocks right after boot:
[...]
[    3.544110] udevd[677]: starting version 182
[    4.125070] cfg80211: Calling CRDA to update world regulatory domain
[    4.499920] RTL871X: module init start
[    4.503973] RTL871X: rtl8723bu v4.3.6.11_12942.20141204_BTCOEX20140507-4E40
[    4.511273] RTL871X: rtl8723bu BT-Coex version = BTCOEX20140507-4E40
[    7.276123] cfg80211: Calling CRDA to update world regulatory domain
[    7.816563] RTL871X: rtw_ndev_init(wlan0)
[    7.823760] usbcore: registered new interface driver rtl8723bu
[    7.829887] RTL871X: module init ret=0
[    8.275916] EXT4-fs (mmcblk1p3): re-mounted. Opts: data=ordered
bootlogd: cannot allocate pseudo tty: No such file or directory
[    8.419817] random: dd urandom read with 105 bits of entropy available
Populating dev cache
[   10.432973] cfg80211: Calling CRDA to update world regulatory domain
hwclock: can't open '/dev/misc/rtc': No such file or directory
Thu Sep 15 23:48:31 UTC 2016
hwclock: can't open '/dev/misc/rtc': No such file or directory
Starting watchdog
[   11.915814] watchdog watchdog0: watchdog did not stop!
[   13.582859] cfg80211: Calling CRDA to update world regulatory domain
[   14.169740] random: nonblocking pool is initialized
update-rc.d: /etc/init.d/run-postinsts exists during rc.d purge (continuing)
 Removing any system startup links for run-postinsts ...
  /etc/rcS.d/S99run-postinsts
INIT: Entering runlevel: 5
Configuring network interfaces... [   14.520549] net eth0: initializing cpsw version 1.12 (0)
[   14.603248] net eth0: phy found : id is : 0x4dd072
[   14.608427] libphy: PHY 4a101000.mdio:01 not found
[   14.613487] net eth0: phy 4a101000.mdio:01 not found on slave 1
[   14.625689] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
udhcpc (v1.23.2) started
Sending discover...
[   16.732824] cfg80211: Calling CRDA to update world regulatory domain
Sending discover...
[   19.882724] cfg80211: Calling CRDA to update world regulatory domain
Sending discover...
[   23.032729] cfg80211: Calling CRDA to update world regulatory domain
No lease, forking to background
[   23.865391] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
done.
Starting system message bus: Setting up watches.
Watches established.
/var/run/dbus/ CREATE system_bus_socket
hwclock: can't open '/dev/misc/rtc': No such file or directory
Starting syslogd/klogd: done
Starting php-fpm [   25.190096] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   25.197402] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   25.991495] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   25.998758] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   26.182841] cfg80211: Calling CRDA to update world regulatory domain
 done
Starting Connection Manager
Starting Hiawatha Web Server: [   26.981252] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   26.988575] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
hiawatha.
dbus[1832]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
Starting crond: dbus[1832]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
OK
[   27.518031]
[   27.519624] =============================================
[   27.525281] [ INFO: possible recursive locking detected ]
[   27.530944] 4.1.15-venus #1 Tainted: G           O
[   27.536236] ---------------------------------------------
[   27.541892] connmand/1959 is trying to acquire lock:
[   27.547094]  (pmutex){+.+...}, at: [<bf0ef664>] usbctrl_vendorreq+0x7c/0x274 [8723bu]
[   27.555649]
[   27.555649] but task is already holding lock:
[   27.561764]  (pmutex){+.+...}, at: [<bf0ee454>] netdev_open+0x28/0x50 [8723bu]
[   27.569468]
[   27.569468] other info that might help us debug this:
[   27.576311]  Possible unsafe locking scenario:
[   27.576311]
[   27.582516]        CPU0
[   27.585075]        ----
[   27.587632]   lock(pmutex);
[   27.590565]   lock(pmutex);
[   27.593497]
[   27.593497]  *** DEADLOCK ***
[   27.593497]
[   27.599704]  May be due to missing lock nesting notation
[   27.599704]
[   27.606822] 2 locks held by connmand/1959:
[   27.611111]  #0:  (rtnl_mutex){+.+.+.}, at: [<c042d050>] devinet_ioctl+0xd0/0x7d4
[   27.618996]  #1:  (pmutex){+.+...}, at: [<bf0ee454>] netdev_open+0x28/0x50 [8723bu]
[   27.627136]
[   27.627136] stack backtrace:
[   27.631706] CPU: 0 PID: 1959 Comm: connmand Tainted: G           O    4.1.15-venus #1
[   27.639914] Hardware name: Generic AM33XX (Flattened Device Tree)
[   27.646326] [<c0014844>] (unwind_backtrace) from [<c0012994>] (show_stack+0x10/0x14)
[   27.654455] [<c0012994>] (show_stack) from [<c0067fe0>] (__lock_acquire+0x1454/0x1da0)
[   27.662759] [<c0067fe0>] (__lock_acquire) from [<c006922c>] (lock_acquire+0xac/0x12c)
[   27.670979] [<c006922c>] (lock_acquire) from [<c04bffd4>] (mutex_lock_interruptible_nested+0x48/0x3bc)
[   27.680833] [<c04bffd4>] (mutex_lock_interruptible_nested) from [<bf0ef664>] (usbctrl_vendorreq+0x7c/0x274 [8723bu])
[   27.692079] [<bf0ef664>] (usbctrl_vendorreq [8723bu]) from [<bf11e9f0>] (usb_read8+0x30/0x3c [8723bu])
[   27.702011] [<bf11e9f0>] (usb_read8 [8723bu]) from [<bf0c1178>] (rtw_read8+0x18/0x1c [8723bu])
[   27.711204] [<bf0c1178>] (rtw_read8 [8723bu]) from [<bf11ceb0>] (rtl8723bu_hal_init+0x30/0xb4c [8723bu])
[   27.721338] [<bf11ceb0>] (rtl8723bu_hal_init [8723bu]) from [<bf1026b4>] (rtw_hal_init+0x18/0x154 [8723bu])
[   27.731727] [<bf1026b4>] (rtw_hal_init [8723bu]) from [<bf0ee20c>] (_netdev_open+0x64/0x284 [8723bu])
[   27.741561] [<bf0ee20c>] (_netdev_open [8723bu]) from [<bf0ee45c>] (netdev_open+0x30/0x50 [8723bu])
[   27.751143] [<bf0ee45c>] (netdev_open [8723bu]) from [<c03c8884>] (__dev_open+0xb8/0x11c)
[   27.759726] [<c03c8884>] (__dev_open) from [<c03c8b08>] (__dev_change_flags+0x94/0x144)
[   27.768123] [<c03c8b08>] (__dev_change_flags) from [<c03c8bd0>] (dev_change_flags+0x18/0x48)
[   27.776978] [<c03c8bd0>] (dev_change_flags) from [<c042d64c>] (devinet_ioctl+0x6cc/0x7d4)
[   27.785559] [<c042d64c>] (devinet_ioctl) from [<c03ae70c>] (sock_ioctl+0x1d8/0x2b0)
[   27.793593] [<c03ae70c>] (sock_ioctl) from [<c011c39c>] (do_vfs_ioctl+0x3f0/0x5c0)
[   27.801533] [<c011c39c>] (do_vfs_ioctl) from [<c011c5a0>] (SyS_ioctl+0x34/0x5c)
[   27.809201] [<c011c5a0>] (SyS_ioctl) from [<c000f1e0>] (ret_fast_syscall+0x0/0x54)
Checking available software versions...
[   28.191668] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
Starting simple-upnpd
[   31.095134] RTL871X: RTW_ADAPTIVITY_EN_AUTO, chplan:0x20, Regulation:0,0
[   31.102220] RTL871X: RTW_ADAPTIVITY_MODE_NORMAL
[   32.523712] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   32.536569] cfg80211: Calling CRDA to update world regulatory domain
[   32.604106] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   32.611164] c_can_platform 481d0000.can: obtain a copy of previously claimed pinctrl
[   32.619469] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   33.212819] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   33.220096] c_can_platform 481d0000.can: obtain a copy of previously claimed pinctrl
[   33.291001] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   33.704635] RTL871X: nolinked power save enter
[   39.083257] RTL871X: RTW_ADAPTIVITY_EN_AUTO, chplan:0x20, Regulation:0,0
[   39.090326] RTL871X: RTW_ADAPTIVITY_MODE_NORMAL
[   40.204562] RTL871X: nolinked power save leave
[   40.425420] RTL871X: rtw_set_802_11_connect(wlan0)  fw_state=0x00000008
[   40.432584] cfg80211: Calling CRDA to update world regulatory domain
[   40.498385] RTL871X: start auth
[   40.503755] RTL871X: auth success, start assoc
[   40.512793] RTL871X: rtw_cfg80211_indicate_connect(wlan0) BSS not found !!
[   40.520058] RTL871X: assoc success
[   40.524101] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   40.956425] RTL871X: send eapol packet
[   40.978771] RTL871X: send eapol packet
[   40.994451] RTL871X: set pairwise key camid:4, addr:98:fc:11:ae:b5:04, kid:0, type:AES
bgscan simple: Failed to enable signal strength monitoring
[   41.024333] RTL871X: set group key camid:5, addr:98:fc:11:ae:b5:04, kid:1, type:AES
[   43.582737] cfg80211: Calling CRDA to update world regulatory domain
[   46.732739] cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
@mpvader
Copy link
Author

mpvader commented Sep 19, 2016

@lwfinger I went ahead and made a clean build of the whole system to cut & paste the bootlog for you, but now the behavior has changed (...): It does reboot now, but only after seeing a kernel deadlock message. See full log below.

If I move that .ko file out of its normal location to make sure it isn't loaded, all works fine again: no kernel deadlocks.

Note that this is a different distro than the IoT one from the Beaglebone organisation. What I am running on the Beaglebone Enhanced is our Venus distro. Similar to @RobertCNelson, I just compile this rtl8723bu driver with its default settings and add it to the rootfs. See the 'add rtl8723bu driver for wifi on bbe' commit for details.

The used kernel sources & config is here:
https://github.com/victronenergy/linux/tree/v4.1.15-bbb5

For anyone interested, binary installer image can be downloaded here:
venus-install-sdcard-beaglebone-20160918102415-bbe-rt8723bu.img.zip

U-Boot SPL 2015.07-venus (Sep 02 2016 - 09:01:50)
reading u-boot.img
reading u-boot.img


U-Boot 2015.07-venus (Sep 02 2016 - 09:01:50 +0200)

       Watchdog enabled
I2C:   ready
DRAM:  1 GiB
MMC:   OMAP SD/MMC: 0, OMAP SD/MMC: 1
Net:   <ethaddr> not set. Validating first E-fuse MAC
cpsw, usb_ether
Hit any key to stop autoboot:  0
switch to partitions #0, OK
mmc0 is current device
SD/MMC found on device 0
reading boot.scr
396 bytes read in 3 ms (128.9 KiB/s)
Running bootscript from mmc0 ...
## Executing script at 82000000
gpio: pin 72 (gpio 72) value is 1
switch to partitions #0, OK
mmc1(part 0) is current device
SD/MMC found on device 1
reading boot.scr
** Unable to read file boot.scr **
reading uEnv.txt
831 bytes read in 4 ms (202.1 KiB/s)
Loaded environment from uEnv.txt
Importing environment from mmc ...
Running uenvcmd ...
30731 bytes read in 27 ms (1.1 MiB/s)
Loaded bbb-venus.dtb
3659280 bytes read in 229 ms (15.2 MiB/s)
Kernel image @ 0x82000000 [ 0x000000 - 0x37d610 ]
## Flattened Device Tree blob at 88000000
   Booting using the fdt blob at 0x88000000
   Loading Device Tree to 8fff5000, end 8ffff80a ... OK

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.1.15-venus (matthijs@matthijs-VirtualBox) (gcc version 5.2.0 (GCC) ) #1 Sun Sep 18 12:28:03 CEST 2016
[    0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] Machine model: TI AM335x BeagleBone Black
[    0.000000] cma: Reserved 16 MiB at 0xbf000000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] AM335X ES2.1 (sgx neon )
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 260624
[    0.000000] Kernel command line: console=ttyO0,115200n8 consoleblank=0 root=/dev/mmcblk1p3 ro rootfstype=ext4 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: 1007408K/1048576K available (4993K kernel code, 322K rwdata, 1752K rodata, 276K init, 8172K bss, 24784K reserved, 16384K cma-reserved, 253952K highmem)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0xf0000000 - 0xff000000   ( 240 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xef800000   ( 760 MB)
[    0.000000]     pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
[    0.000000]     modules : 0xbf000000 - 0xbfe00000   (  14 MB)
[    0.000000]       .text : 0xc0008000 - 0xc069e928   (6747 kB)
[    0.000000]       .init : 0xc069f000 - 0xc06e4000   ( 276 kB)
[    0.000000]       .data : 0xc06e4000 - 0xc0734a38   ( 323 kB)
[    0.000000]        .bss : 0xc0734a38 - 0xc0f2fc18   (8173 kB)
[    0.000000] Running RCU self tests
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] IRQ: Found an INTC at 0xfa200000 (revision 5.0) with 128 interrupts
[    0.000000] OMAP clockevent source: timer2 at 24000000 Hz
[    0.000013] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
[    0.000033] clocksource timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[    0.000076] OMAP clocksource: timer1 at 24000000 Hz
[    0.000740] Console: colour dummy device 80x30
[    0.000791] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.000800] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.000806] ... MAX_LOCK_DEPTH:          48
[    0.000812] ... MAX_LOCKDEP_KEYS:        8191
[    0.000817] ... CLASSHASH_SIZE:          4096
[    0.000824] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.000830] ... MAX_LOCKDEP_CHAINS:      65536
[    0.000835] ... CHAINHASH_SIZE:          32768
[    0.000842]  memory used by lock dependency info: 5167 kB
[    0.000848]  per task-struct memory footprint: 1152 bytes
[    0.000872] Calibrating delay loop... 996.14 BogoMIPS (lpj=4980736)
[    0.078959] pid_max: default: 32768 minimum: 301
[    0.079166] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.079179] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.081412] CPU: Testing write buffer coherency: ok
[    0.082599] Setting up static identity map for 0x80008200 - 0x80008258
[    0.086563] devtmpfs: initialized
[    0.111885] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[    0.147582] omap_hwmod: tptc0 using broken dt data from edma
[    0.147984] omap_hwmod: tptc1 using broken dt data from edma
[    0.148369] omap_hwmod: tptc2 using broken dt data from edma
[    0.156162] omap_hwmod: debugss: _wait_target_disable failed
[    0.211240] clocksource jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.213692] pinctrl core: initialized pinctrl subsystem
[    0.218330] NET: Registered protocol family 16
[    0.224829] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.227528] cpuidle: using governor ladder
[    0.227566] cpuidle: using governor menu
[    0.235093] OMAP GPIO hardware version 0.1
[    0.253052] No ATAGs?
[    0.253084] hw-breakpoint: debug architecture 0x4 unsupported.
[    0.322550] edma-dma-engine edma-dma-engine.0: TI EDMA DMA engine driver
[    0.326994] usbcore: registered new interface driver usbfs
[    0.327152] usbcore: registered new interface driver hub
[    0.327303] usbcore: registered new device driver usb
[    0.328195] omap_i2c 44e0b000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c0_pins, deferring probe
[    0.328292] omap_i2c 4802a000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c1_pins, deferring probe
[    0.331810] Switched to clocksource timer1
[    0.469410] NET: Registered protocol family 2
[    0.471124] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.471344] TCP bind hash table entries: 8192 (order: 6, 294912 bytes)
[    0.473818] TCP: Hash tables configured (established 8192 bind 8192)
[    0.474039] UDP hash table entries: 512 (order: 3, 40960 bytes)
[    0.474361] UDP-Lite hash table entries: 512 (order: 3, 40960 bytes)
[    0.475269] NET: Registered protocol family 1
[    0.477145] CPU PMU: Failed to parse /pmu/interrupt-affinity[0]
[    0.477216] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
[    0.480983] futex hash table entries: 256 (order: 1, 11264 bytes)
[    0.490366] VFS: Disk quotas dquot_6.6.0
[    0.490468] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.496312] bounce: pool size: 64 pages
[    0.496447] io scheduler noop registered
[    0.496465] io scheduler deadline registered
[    0.496503] io scheduler cfq registered (default)
[    0.499715] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568
[    0.503310] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.509760] omap_uart 44e09000.serial: no wakeirq for uart0
[    0.510339] 44e09000.serial: ttyO0 at MMIO 0x44e09000 (irq = 154, base_baud = 3000000) is a OMAP UART0
[    1.087645] console [ttyO0] enabled
[    1.094492] omap_uart 48024000.serial: no wakeirq for uart2
[    1.100624] 48024000.serial: ttyO2 at MMIO 0x48024000 (irq = 155, base_baud = 3000000) is a OMAP UART2
[    1.112109] omap_uart 481a8000.serial: no wakeirq for uart4
[    1.118231] 481a8000.serial: ttyO4 at MMIO 0x481a8000 (irq = 156, base_baud = 3000000) is a OMAP UART4
[    1.129515] omap_uart 481aa000.serial: no wakeirq for uart5
[    1.135673] 481aa000.serial: ttyO5 at MMIO 0x481aa000 (irq = 157, base_baud = 3000000) is a OMAP UART5
[    1.148630] omap_rng 48310000.rng: OMAP Random Number Generator ver. 20
[    1.188098] brd: module loaded
[    1.209298] loop: module loaded
[    1.214476] vcan: Virtual CAN interface driver
[    1.219151] slcan: serial line CAN interface driver
[    1.224307] slcan: 10 dynamic interface channels.
[    1.229250] CAN device driver interface
[    1.235764] c_can_platform 481cc000.can: c_can_platform device registered (regs=fa1cc000, irq=163)
[    1.246994] c_can_platform 481d0000.can: c_can_platform device registered (regs=fa1d0000, irq=164)
[    1.257929] usbcore: registered new interface driver asix
[    1.263770] usbcore: registered new interface driver ax88179_178a
[    1.270264] usbcore: registered new interface driver cdc_ether
[    1.276551] usbcore: registered new interface driver smsc95xx
[    1.282701] usbcore: registered new interface driver net1080
[    1.288735] usbcore: registered new interface driver cdc_subset
[    1.295062] usbcore: registered new interface driver zaurus
[    1.301101] usbcore: registered new interface driver cdc_ncm
[    1.317387] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.324322] ehci-omap: OMAP-EHCI Host Controller driver
[    1.330152] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    1.336876] usbcore: registered new interface driver cdc_wdm
[    1.343017] usbcore: registered new interface driver usbtest
[    1.351595] 47401300.usb-phy supply vcc not found, using dummy regulator
[    1.368088] 47401b00.usb-phy supply vcc not found, using dummy regulator
[    1.380365] musb-hdrc musb-hdrc.1.auto: MUSB HDRC host driver
[    1.389676] musb-hdrc musb-hdrc.1.auto: new USB bus registered, assigned bus number 1
[    1.399746] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    1.406923] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.414510] usb usb1: Product: MUSB HDRC host driver
[    1.419715] usb usb1: Manufacturer: Linux 4.1.15-venus musb-hcd
[    1.425933] usb usb1: SerialNumber: musb-hdrc.1.auto
[    1.435309] hub 1-0:1.0: USB hub found
[    1.440088] hub 1-0:1.0: 1 port detected
[    1.450978] mousedev: PS/2 mouse device common for all mice
[    1.460076] i2c /dev entries driver
[    1.463908] Driver for 1-wire Dallas network protocol.
[    1.474448] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[    1.484159] omap_hsmmc 48060000.mmc: Got CD GPIO
[    1.569473] mmc0: host does not support reading read-only switch, assuming write-enable
[    1.581395] ledtrig-cpu: registered to indicate activity on CPUs
[    1.588289] usbcore: registered new interface driver usbhid
[    1.594167] usbhid: USB HID core driver
[    1.599211] oprofile: using arm/armv7
[    1.603724] Initializing XFRM netlink socket
[    1.608527] NET: Registered protocol family 10
[    1.615713] mmc0: new high speed SDHC card at address 59b4
[    1.628473] mmcblk0: mmc0:59b4 USD   7.51 GiB
[    1.638254] sit: IPv6 over IPv4 tunneling driver
[    1.645312] NET: Registered protocol family 17
[    1.650050] NET: Registered protocol family 15
[    1.654781] can: controller area network core (rev 20120528 abi 9)
[    1.661386] NET: Registered protocol family 29
[    1.666166] can: raw protocol (rev 20120528)
[    1.670780] can: broadcast manager protocol (rev 20120528 t)
[    1.677223] Key type dns_resolver registered
[    1.681922] omap_voltage_late_init: Voltage driver support not added
[    1.689575] ThumbEE CPU extension supported.
[    1.695792]  mmcblk0: p1
[    1.749119] tps65217 0-0024: TPS65217 ID 0x6 version 1.2
[    1.754896] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz
[    1.761980] mmc1: MAN_BKOPS_EN bit is not set
[    1.774080] mmc1: new high speed MMC card at address 0001
[    1.781153] mmcblk1: mmc1:0001 P1XXXX 3.60 GiB
[    1.787072] mmcblk1boot0: mmc1:0001 P1XXXX partition 1 2.00 MiB
[    1.794282] mmcblk1boot1: mmc1:0001 P1XXXX partition 2 2.00 MiB
[    1.803970]  mmcblk1: p1 p2 p3 p4 < p5 p6 >
[    1.851909] usb 1-1: new high-speed USB device number 2 using musb-hdrc
[    1.992187] usb 1-1: New USB device found, idVendor=0424, idProduct=2514
[    1.999231] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.009790] hub 1-1:1.0: USB hub found
[    2.014519] hub 1-1:1.0: 4 ports detected
[    2.291861] usb 1-1.4: new high-speed USB device number 3 using musb-hdrc
[    2.412581] usb 1-1.4: New USB device found, idVendor=0bda, idProduct=b720
[    2.419796] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.427485] usb 1-1.4: Product: 802.11n WLAN Adapter
[    2.432707] usb 1-1.4: Manufacturer: Realtek
[    2.437184] usb 1-1.4: SerialNumber: 00e04c000001
[    2.781853] omap_i2c 4802a000.i2c: timeout waiting for bus ready
[    2.788282] rtc-pcf8523: probe of 1-0068 failed with error -110
[    2.794568] omap_i2c 4802a000.i2c: bus 1 rev0.11 at 400 kHz
[    2.861876] davinci_mdio 4a101000.mdio: davinci mdio revision 1.6
[    2.868287] davinci_mdio 4a101000.mdio: detected phy mask fffffffe
[    2.877922] libphy: 4a101000.mdio: probed
[    2.882218] davinci_mdio 4a101000.mdio: phy[0]: device 4a101000.mdio:00, driver Atheros 8035 ethernet
[    2.892974] cpsw 4a100000.ethernet: Detected MACID = b0:d5:cc:f1:b4:c2
[    2.903078] hctosys: unable to open rtc device (rtc0)
[    2.934569] EXT4-fs (mmcblk1p3): INFO: recovery required on readonly filesystem
[    2.942314] EXT4-fs (mmcblk1p3): write access will be enabled during recovery
[    3.130917] EXT4-fs (mmcblk1p3): recovery complete
[    3.140115] EXT4-fs (mmcblk1p3): mounted filesystem with ordered data mode. Opts: (null)
[    3.148824] VFS: Mounted root (ext4 filesystem) readonly on device 179:11.
[    3.160506] devtmpfs: mounted
[    3.164199] Freeing unused kernel memory: 276K (c069f000 - c06e4000)
INIT: version 2.88 booting
[    3.544662] EXT4-fs (mmcblk1p5): recovery complete
[    3.550747] EXT4-fs (mmcblk1p5): mounted filesystem with ordered data mode. Opts: (null)
[    3.565968] EXT4-fs (mmcblk1p6): recovery complete
[    3.571039] EXT4-fs (mmcblk1p6): mounted filesystem with ordered data mode. Opts: (null)
Starting udev
udev: Not using udev cache because of changes detected in the following files:
udev:     /proc/version /proc/cmdline /proc/devices
udev:     lib/udev/rules.d/* etc/udev/rules.d/*
udev: The udev cache will be regenerated. To identify the detected changes,
udev: compare the cached sysconf at   /etc/udev/cache.data
udev: against the current sysconf at  /dev/shm/udev.cache
[    3.816733] udevd[680]: starting version 182
[    4.442843] cfg80211: Calling CRDA to update world regulatory domain
[    4.803035] RTL871X: module init start
[    4.806991] RTL871X: rtl8723bu v4.3.6.11_12942.20141204_BTCOEX20140507-4E40
[    4.814346] RTL871X: rtl8723bu BT-Coex version = BTCOEX20140507-4E40
udevd[686]: rename '/dev/disk/by-path/platform-481d8000.mmc.udev-tmp' '/dev/disk/by-path/platform-481d8000.mmc' failed: No such file or directory

[    7.593521] cfg80211: Calling CRDA to update world regulatory domain
[    8.083914] RTL871X: rtw_ndev_init(wlan0)
[    8.090919] usbcore: registered new interface driver rtl8723bu
[    8.097116] RTL871X: module init ret=0
[    8.426998] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[    8.548834] EXT4-fs (mmcblk1p3): re-mounted. Opts: data=ordered
bootlogd: cannot allocate pseudo tty: No such file or directory
[    8.696976] random: dd urandom read with 114 bits of entropy available
Populating dev cache
hwclock: can't open '/dev/misc/rtc': No such file or directory
Sun Sep 18 10:39:31 UTC 2016
hwclock: can't open '/dev/misc/rtc': No such file or directory
Starting watchdog
[    9.784386] watchdog watchdog0: watchdog did not stop!
[   10.743379] cfg80211: Calling CRDA to update world regulatory domain
INIT: Entering runlevel: 5
Configuring network interfaces... [   11.489161] net eth0: initializing cpsw version 1.12 (0)
[   11.572423] net eth0: phy found : id is : 0x4dd072
[   11.577604] libphy: PHY 4a101000.mdio:01 not found
[   11.582657] net eth0: phy 4a101000.mdio:01 not found on slave 1
[   11.594812] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
udhcpc (v1.23.2) started
Sending discover...
[   13.891921] cfg80211: Calling CRDA to update world regulatory domain
Sending discover...
[   17.041978] cfg80211: Calling CRDA to update world regulatory domain
Sending discover...
[   19.002350] random: nonblocking pool is initialized
[   20.191914] cfg80211: Calling CRDA to update world regulatory domain
No lease, forking to background
[   20.833834] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
done.
Starting system message bus: Setting up watches.
Watches established.
/var/run/dbus/ CREATE system_bus_socket
hwclock: can't open '/dev/misc/rtc': No such file or directory
Starting syslogd/klogd: done
Starting php-fpm [   22.397826] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   22.405085] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   23.342020] cfg80211: Calling CRDA to update world regulatory domain
 done
Starting Connection Manager
Starting Hiawatha Web Server: [   24.100869] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   24.108175] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
hiawatha.
Starting crond: dbus[1411]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
OK
Checking available software versions...
dbus[1411]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
[   25.156369] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   25.163670] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   25.309574] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
Starting simple-upnpd
[   26.214150] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   26.221352] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   26.492127] cfg80211: Calling CRDA to update world regulatory domain

beaglebone login: [   27.151535] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   27.158852] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   28.179836] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   28.187152] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   29.023484] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   29.030741] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready

beaglebone login: r[   29.642136] cfg80211: Calling CRDA to update world regulatory domain
oot
Last login: Sun Sep 18 10:39:19 +0000 2016 on /dev/ttyO0.
root@beaglebone:~# reboot
[   32.792161] cfg80211: Calling CRDA to update world regulatory domain

Broadcast message from root@beaglebone (ttyO0) (Sun Sep 18 10:39:53 2016):
The system is going down for reboot NOW!
INIT: Sending processes the TERM signal
root@beaglebone:~# [   35.942075] cfg80211: Calling CRDA to update world regulatory domain
INIT: Sending processes the KILL signal
[   39.091998] cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
Stopping simple-upnpd
Stopping system message bus
hwclock: can't open '/dev/misc/rtc': No such file or directory
Stopping syslogd/klogd: stopped syslogd (pid 1420)
stopped klogd (pid 1423)
done
Stopping Connection Manager
Stopping crond: OK
Gracefully shutting down php-fpm . done
Stopping Hiawatha Web Server: stopped /usr/sbin/hiawatha (pid 1545)
hiawatha.
Deconfiguring network interfaces... done.
Sending all processes the TERM signal...
Sending all processes the KILL signal...
Unmounting remote filesystems...
Deactivating swap...
Unmounting local filesystems...
[   50.284194] EXT4-fs (mmcblk1p3): re-mounted. Opts: data=ordered
Rebooting... [   52.462331] musb-hdrc musb-hdrc.1.auto: remove, state 1
[   52.468442] usb usb1: USB disconnect, device number 1
[   52.473813] usb 1-1: USB disconnect, device number 2
[   52.479031] usb 1-1.4: USB disconnect, device number 3
[   52.494209] ------------[ cut here ]------------
[   52.499310] WARNING: CPU: 0 PID: 1791 at /media/venusbuilds/wipbbbjethro/build/tmp-glibc/work-shared/beaglebone/kernel-source/net/wireless/core.c:778 wiphy_unregister+0x2b4/0x2b8 [cfg80211]()
[   52.517247] Modules linked in: 8723bu(O) ti_am335x_adc kfifo_buf industrialio cfg80211 rfkill ti_am335x_tsc ti_am335x_tscadc
[   52.529104] CPU: 0 PID: 1791 Comm: reboot Tainted: G           O    4.1.15-venus #1
[   52.537148] Hardware name: Generic AM33XX (Flattened Device Tree)
[   52.543596] [<c0014844>] (unwind_backtrace) from [<c0012994>] (show_stack+0x10/0x14)
[   52.551733] [<c0012994>] (show_stack) from [<c00326d0>] (warn_slowpath_common+0x84/0xb0)
[   52.560268] [<c00326d0>] (warn_slowpath_common) from [<c0032798>] (warn_slowpath_null+0x1c/0x24)
[   52.569604] [<c0032798>] (warn_slowpath_null) from [<bf015aa4>] (wiphy_unregister+0x2b4/0x2b8 [cfg80211])
[   52.580132] [<bf015aa4>] (wiphy_unregister [cfg80211]) from [<bf11a24c>] (rtw_wdev_unregister+0x48/0x4c [8723bu])
[   52.591166] [<bf11a24c>] (rtw_wdev_unregister [8723bu]) from [<bf1078d8>] (rtw_unregister_netdevs+0x38/0x64 [8723bu])
[   52.602502] [<bf1078d8>] (rtw_unregister_netdevs [8723bu]) from [<bf108ee4>] (rtw_dev_remove+0x1c/0x74 [8723bu])
[   52.613301] [<bf108ee4>] (rtw_dev_remove [8723bu]) from [<c0308bd4>] (usb_unbind_interface+0x7c/0x278)
[   52.623097] [<c0308bd4>] (usb_unbind_interface) from [<c02a942c>] (__device_release_driver+0x70/0xe4)
[   52.632788] [<c02a942c>] (__device_release_driver) from [<c02a94c0>] (device_release_driver+0x20/0x2c)
[   52.642566] [<c02a94c0>] (device_release_driver) from [<c02a8f18>] (bus_remove_device+0xdc/0x108)
[   52.651889] [<c02a8f18>] (bus_remove_device) from [<c02a629c>] (device_del+0x110/0x210)
[   52.660287] [<c02a629c>] (device_del) from [<c03067c4>] (usb_disable_device+0xa0/0x1e8)
[   52.668700] [<c03067c4>] (usb_disable_device) from [<c02fe134>] (usb_disconnect+0x74/0x280)
[   52.677475] [<c02fe134>] (usb_disconnect) from [<c02fe2d0>] (usb_disconnect+0x210/0x280)
[   52.685974] ---[ end trace c88cc1f83d44e9f4 ]---
[   52.696693] RTL871X: rtw_ndev_uninit(wlan0)
[   52.714998]
[   52.716582] =============================================
[   52.722240] [ INFO: possible recursive locking detected ]
[   52.727902] 4.1.15-venus #1 Tainted: G        W  O
[   52.733194] ---------------------------------------------
[   52.738851] reboot/1791 is trying to acquire lock:
[   52.743871]  (&(plock)->rlock){+.....}, at: [<bf0f6a90>] rtw_free_stainfo+0x28/0x360 [8723bu]
[   52.753137]
[   52.753137] but task is already holding lock:
[   52.759249]  (&(plock)->rlock){+.....}, at: [<bf0f999c>] free_mlme_ap_info+0x44/0x64 [8723bu]
[   52.768304]
[   52.768304] other info that might help us debug this:
[   52.775147]  Possible unsafe locking scenario:
[   52.775147]
[   52.781350]        CPU0
[   52.783907]        ----
[   52.786464]   lock(&(plock)->rlock);
[   52.790216]   lock(&(plock)->rlock);
[   52.793966]
[   52.793966]  *** DEADLOCK ***
[   52.793966]
[   52.800170]  May be due to missing lock nesting notation
[   52.800170]
[   52.807286] 9 locks held by reboot/1791:
[   52.811393]  #0:  (reboot_mutex){+.+.+.}, at: [<c005139c>] SyS_reboot+0x90/0x1d8
[   52.819183]  #1:  (&dev->mutex){......}, at: [<c02a7a38>] device_shutdown+0x84/0x1ec
[   52.827331]  #2:  (&dev->mutex){......}, at: [<c02a7a48>] device_shutdown+0x94/0x1ec
[   52.835472]  #3:  (usb_bus_list_lock){+.+.+.}, at: [<c0303458>] usb_remove_hcd+0x98/0x1fc
[   52.844076]  #4:  (&dev->mutex){......}, at: [<c02fe100>] usb_disconnect+0x40/0x280
[   52.852127]  #5:  (&dev->mutex){......}, at: [<c02fe100>] usb_disconnect+0x40/0x280
[   52.860175]  #6:  (&dev->mutex){......}, at: [<c02fe100>] usb_disconnect+0x40/0x280
[   52.868225]  #7:  (&dev->mutex){......}, at: [<c02a94b8>] device_release_driver+0x18/0x2c
[   52.876825]  #8:  (&(plock)->rlock){+.....}, at: [<bf0f999c>] free_mlme_ap_info+0x44/0x64 [8723bu]
[   52.886326]
[   52.886326] stack backtrace:
[   52.890897] CPU: 0 PID: 1791 Comm: reboot Tainted: G        W  O    4.1.15-venus #1
[   52.898921] Hardware name: Generic AM33XX (Flattened Device Tree)
[   52.905332] [<c0014844>] (unwind_backtrace) from [<c0012994>] (show_stack+0x10/0x14)
[   52.913457] [<c0012994>] (show_stack) from [<c0067fe0>] (__lock_acquire+0x1454/0x1da0)
[   52.921760] [<c0067fe0>] (__lock_acquire) from [<c006922c>] (lock_acquire+0xac/0x12c)
[   52.929983] [<c006922c>] (lock_acquire) from [<c04c1f14>] (_raw_spin_lock_bh+0x44/0x54)
[   52.938468] [<c04c1f14>] (_raw_spin_lock_bh) from [<bf0f6a90>] (rtw_free_stainfo+0x28/0x360 [8723bu])
[   52.948290] [<bf0f6a90>] (rtw_free_stainfo [8723bu]) from [<bf0f99a8>] (free_mlme_ap_info+0x50/0x64 [8723bu])
[   52.958848] [<bf0f99a8>] (free_mlme_ap_info [8723bu]) from [<bf108dc8>] (rtw_usb_if1_deinit+0x34/0xa4 [8723bu])
[   52.969591] [<bf108dc8>] (rtw_usb_if1_deinit [8723bu]) from [<bf108f30>] (rtw_dev_remove+0x68/0x74 [8723bu])
[   52.979985] [<bf108f30>] (rtw_dev_remove [8723bu]) from [<c0308bd4>] (usb_unbind_interface+0x7c/0x278)
[   52.989750] [<c0308bd4>] (usb_unbind_interface) from [<c02a942c>] (__device_release_driver+0x70/0xe4)
[   52.999421] [<c02a942c>] (__device_release_driver) from [<c02a94c0>] (device_release_driver+0x20/0x2c)
[   53.009181] [<c02a94c0>] (device_release_driver) from [<c02a8f18>] (bus_remove_device+0xdc/0x108)
[   53.018487] [<c02a8f18>] (bus_remove_device) from [<c02a629c>] (device_del+0x110/0x210)
[   53.026882] [<c02a629c>] (device_del) from [<c03067c4>] (usb_disable_device+0xa0/0x1e8)
[   53.035277] [<c03067c4>] (usb_disable_device) from [<c02fe134>] (usb_disconnect+0x74/0x280)
[   53.044036] [<c02fe134>] (usb_disconnect) from [<c02fe2d0>] (usb_disconnect+0x210/0x280)
[   53.055740] musb-hdrc musb-hdrc.1.auto: USB bus 1 deregistered
[   53.062471] udc musb-hdrc.0.auto: releasing 'musb-hdrc.0.auto'
[   53.069481] reboot: Restarting system

U-Boot SPL 2015.07-venus (Sep 02 2016 - 09:01:50)
reading u-boot.img
reading u-boot.img


U-Boot 2015.07-venus (Sep 02 2016 - 09:01:50 +0200)

       Watchdog enabled
I2C:   ready
DRAM:  1 GiB
MMC:   OMAP SD/MMC: 0, OMAP SD/MMC: 1
Net:   <ethaddr> not set. Validating first E-fuse MAC
cpsw, usb_ether
Hit any key to stop autoboot:  0
switch to partitions #0, OK
mmc0 is current device
SD/MMC found on device 0
reading boot.scr
396 bytes read in 4 ms (96.7 KiB/s)
Running bootscript from mmc0 ...
## Executing script at 82000000
gpio: pin 72 (gpio 72) value is 1
switch to partitions #0, OK
mmc1(part 0) is current device

@lwfinger
Copy link
Owner

As an aside, blacklisting a driver is a lot easier than moving it. In addition, you do not have crda installed in your system. It isn't necessary, but having it would remove all those failure messages from your log.

Did the network work is the case above?

The possible deadlock warning is something that needs attention, but it usually is benign. In addition, it only appears on removal of the device.

The WARNING: CPU: 0 PID: 1791 at /media/venusbuilds/wipbbbjethro/build/tmp-glibc/work-shared/beaglebone/kernel-source/net/wireless/core.c:778 wiphy_unregister+0x2b4/0x2b8 cfg80211 may be responsible for the locking warning.

@RobertCNelson
Copy link

Here's some more details:

debian@arm:~$ dmesg | grep RTL
[    3.051249] musb-hdrc: MHDRC RTL version 2.0 
[    3.061751] musb-hdrc: MHDRC RTL version 2.0 
[   24.665566] RTL871X: module init start
[   24.665572] RTL871X: rtl8723bu v4.3.6.11_12942.20141204_BTCOEX20140507-4E40
[   24.665574] RTL871X: rtl8723bu BT-Coex version = BTCOEX20140507-4E40
[   25.543205] RTL871X: rtw_ndev_init(wlan0)
[   25.660080] RTL871X: module init ret=0
[   26.566004] RTL871X: RTW_ADAPTIVITY_EN_AUTO, chplan:0x20, Regulation:0,0
[   26.572848] RTL871X: RTW_ADAPTIVITY_MODE_NORMAL
[   30.170148] RTL871X: nolinked power save enter
[   31.047917] RTL871X: RTW_ADAPTIVITY_EN_AUTO, chplan:0x20, Regulation:0,0
[   31.054733] RTL871X: RTW_ADAPTIVITY_MODE_NORMAL
[   31.690974] RTL871X: nolinked power save leave
[   31.904252] RTL871X: rtw_set_802_11_connect(wlan0)  fw_state=0x00000008
[   31.933099] RTL871X: start auth
[   31.942345] RTL871X: auth success, start assoc
[   31.978136] RTL871X: rtw_cfg80211_indicate_connect(wlan0) BSS not found !!
[   31.985125] RTL871X: assoc success
[   32.017594] RTL871X: send eapol packet
[   32.033803] RTL871X: send eapol packet
[   32.131883] RTL871X: set pairwise key camid:4, addr:2c:f7:f1:06:1d:68, kid:0, type:AES
[   32.144356] RTL871X: set group key camid:5, addr:2c:f7:f1:06:1d:68, kid:1, type:AES

call reboot:

[  OK  ] Reached target Shutdown.
[   67.463821] watchdog watchdog0: watchdog did not stop!
[   67.505056] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[   67.532646] systemd-journald[554]: Received SIGTERM from PID 1 (systemd-shutdow).
[   67.549066] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[   67.575314] systemd-shutdown[1]: Hardware watchdog 'OMAP Watchdog', version 0
[   67.584202] systemd-shutdown[1]: Unmounting file systems.
[   67.591132] systemd-shutdown[1]: Remounting '/' read-only with options 'errors=remount-ro,data=ordered'.
[   67.687322] EXT4-fs (mmcblk0p1): re-mounted. Opts: errors=remount-ro,data=ordered
[   67.700664] systemd-shutdown[1]: Remounting '/' read-only with options 'errors=remount-ro,data=ordered'.
[   67.711454] EXT4-fs (mmcblk0p1): re-mounted. Opts: errors=remount-ro,data=ordered
[   67.719198] systemd-shutdown[1]: All filesystems unmounted.
[   67.725128] systemd-shutdown[1]: Deactivating swaps.
[   67.730579] systemd-shutdown[1]: All swaps deactivated.
[   67.735951] systemd-shutdown[1]: Detaching loop devices.
[   67.744949] systemd-shutdown[1]: All loop devices detached.
[   67.750673] systemd-shutdown[1]: Detaching DM devices.
[   67.756499] systemd-shutdown[1]: All DM devices detached.
[   67.778153] systemd-shutdown[1]: Failed to read reboot parameter file: No such file or directory
[   67.787505] systemd-shutdown[1]: Rebooting.
[   67.798378] musb-hdrc musb-hdrc.1.auto: remove, state 1
[   67.803756] usb usb1: USB disconnect, device number 1
[   67.808861] usb 1-1: USB disconnect, device number 2
[   67.813870] usb 1-1.3: USB disconnect, device number 3
[   67.968936] RTL871X: rtw_cmd_thread: DriverStopped(0) SurpriseRemoved(1) break at line 452

(without the usb module installed)

[  OK  ] Reached target Shutdown.
[   57.007062] watchdog watchdog0: watchdog did not stop!
[   57.048119] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[   57.074182] systemd-journald[536]: Received SIGTERM from PID 1 (systemd-shutdow).
[   57.090878] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[   57.115555] systemd-shutdown[1]: Hardware watchdog 'OMAP Watchdog', version 0
[   57.124509] systemd-shutdown[1]: Unmounting file systems.
[   57.131352] systemd-shutdown[1]: Remounting '/' read-only with options 'errors=remount-ro,data=ordered'.
[   57.462285] EXT4-fs (mmcblk0p1): re-mounted. Opts: errors=remount-ro,data=ordered
[   57.476658] systemd-shutdown[1]: Remounting '/' read-only with options 'errors=remount-ro,data=ordered'.
[   57.487498] EXT4-fs (mmcblk0p1): re-mounted. Opts: errors=remount-ro,data=ordered
[   57.495187] systemd-shutdown[1]: All filesystems unmounted.
[   57.500934] systemd-shutdown[1]: Deactivating swaps.
[   57.506364] systemd-shutdown[1]: All swaps deactivated.
[   57.511765] systemd-shutdown[1]: Detaching loop devices.
[   57.522152] systemd-shutdown[1]: All loop devices detached.
[   57.527973] systemd-shutdown[1]: Detaching DM devices.
[   57.534136] systemd-shutdown[1]: All DM devices detached.
[   57.554420] systemd-shutdown[1]: Failed to read reboot parameter file: No such file or directory
[   57.563496] systemd-shutdown[1]: Rebooting.
[   57.573927] musb-hdrc musb-hdrc.1.auto: remove, state 4
[   57.579337] usb usb1: USB disconnect, device number 1
[   57.584453] usb 1-1: USB disconnect, device number 2
[   57.591645] musb-hdrc musb-hdrc.1.auto: USB bus 1 deregistered
[   57.614004] reboot: Restarting system

U-Boot SPL 2016.09-00001-gc6ebf08 (Sep 12 2016 - 15:30:47)
Trying to boot from MMC1
Expected Linux image is not found. Trying to start U-boot


U-Boot 2016.09-00001-gc6ebf08 (Sep 12 2016 - 15:30:47 -0500), Build: jenkins-github_Bootloader-Builder-455

@sancloud
Copy link

I have found the system is more reliable at rebooting when it isn't associated with an AP.
If it is in client mode, it can be up and scan to identify the available AP's and it will reboot.
If its associated then we have problems.

@lwfinger
Copy link
Owner

I am a little confused. On reboot, the NIC is never associated with any AP. I understand that you might have problems shutting down while associated. Is that what is happening?

@lwfinger
Copy link
Owner

I just found a lock that is not needed and pushed a fix. Does this help?

@mpvader
Copy link
Author

mpvader commented Sep 21, 2016

@lwfinger wrote:

As an aside, blacklisting a driver is a lot easier than moving it. In addition, you do not have crda installed in your system. It isn't necessary, but having it would remove all those failure messages from your log.

Yes, thanks. I took crda out a while ago, but it can go back in now.

Did the network work is the case above?

Yes.


@sancloud wrote:

I have found the system is more reliable at rebooting when it isn't associated with an AP.
If it is in client mode, it can be up and scan to identify the available AP's and it will reboot.
If its associated then we have problems.

there is a bit more nuance to it: just enabling wifi (using connman) is enough to make it get stuck.


@lwfinger wrote:

I just found a lock that is not needed and pushed a fix. Does this help?

No. (After enabling wifi) it is still stuck at rebooting. Also there is a deadlock error when enabling wifi:

(...)
[    1.258171] usbcore: registered new interface driver asix
[    1.264022] usbcore: registered new interface driver ax88179_178a
[    1.270516] usbcore: registered new interface driver cdc_ether
[    1.276802] usbcore: registered new interface driver smsc95xx
[    1.282951] usbcore: registered new interface driver net1080
[    1.288984] usbcore: registered new interface driver cdc_subset
[    1.295313] usbcore: registered new interface driver zaurus
[    1.301352] usbcore: registered new interface driver cdc_ncm
[    1.317538] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.324479] ehci-omap: OMAP-EHCI Host Controller driver
[    1.330312] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    1.337034] usbcore: registered new interface driver cdc_wdm
[    1.343175] usbcore: registered new interface driver usbtest
[    1.351740] 47401300.usb-phy supply vcc not found, using dummy regulator
[    1.368241] 47401b00.usb-phy supply vcc not found, using dummy regulator
[    1.380523] musb-hdrc musb-hdrc.1.auto: MUSB HDRC host driver
[    1.389835] musb-hdrc musb-hdrc.1.auto: new USB bus registered, assigned bus number 1
[    1.399911] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    1.407082] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.414673] usb usb1: Product: MUSB HDRC host driver
[    1.419878] usb usb1: Manufacturer: Linux 4.1.15-venus musb-hcd
[    1.426097] usb usb1: SerialNumber: musb-hdrc.1.auto
[    1.435486] hub 1-0:1.0: USB hub found
[    1.440266] hub 1-0:1.0: 1 port detected
[    1.451144] mousedev: PS/2 mouse device common for all mice
[    1.460263] i2c /dev entries driver
[    1.464095] Driver for 1-wire Dallas network protocol.
[    1.474630] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[    1.484347] omap_hsmmc 48060000.mmc: Got CD GPIO
[    1.569828] mmc0: host does not support reading read-only switch, assuming write-enable
[    1.581739] ledtrig-cpu: registered to indicate activity on CPUs
[    1.588629] usbcore: registered new interface driver usbhid
[    1.594507] usbhid: USB HID core driver
[    1.599549] oprofile: using arm/armv7
[    1.604070] Initializing XFRM netlink socket
[    1.608877] NET: Registered protocol family 10
[    1.616091] mmc0: new high speed SDHC card at address 59b4
[    1.628839] mmcblk0: mmc0:59b4 USD   7.51 GiB
[    1.638649] sit: IPv6 over IPv4 tunneling driver
[    1.645724] NET: Registered protocol family 17
[    1.650462] NET: Registered protocol family 15
[    1.655194] can: controller area network core (rev 20120528 abi 9)
[    1.661800] NET: Registered protocol family 29
[    1.666579] can: raw protocol (rev 20120528)
[    1.671193] can: broadcast manager protocol (rev 20120528 t)
[    1.677628] Key type dns_resolver registered
[    1.682332] omap_voltage_late_init: Voltage driver support not added
[    1.689982] ThumbEE CPU extension supported.
[    1.696218]  mmcblk0: p1
[    1.749624] tps65217 0-0024: TPS65217 ID 0x6 version 1.2
[    1.755396] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz
[    1.762470] mmc1: MAN_BKOPS_EN bit is not set
[    1.774460] mmc1: new high speed MMC card at address 0001
[    1.781552] mmcblk1: mmc1:0001 P1XXXX 3.60 GiB
[    1.787469] mmcblk1boot0: mmc1:0001 P1XXXX partition 1 2.00 MiB
[    1.794685] mmcblk1boot1: mmc1:0001 P1XXXX partition 2 2.00 MiB
[    1.804414]  mmcblk1: p1 p2 p3 p4 < p5 p6 >
[    1.852263] usb 1-1: new high-speed USB device number 2 using musb-hdrc
[    1.992558] usb 1-1: New USB device found, idVendor=0424, idProduct=2514
[    1.999600] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.009804] hub 1-1:1.0: USB hub found
[    2.014633] hub 1-1:1.0: 4 ports detected
[    2.292217] usb 1-1.4: new high-speed USB device number 3 using musb-hdrc
[    2.412898] usb 1-1.4: New USB device found, idVendor=0bda, idProduct=b720
[    2.420113] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.427802] usb 1-1.4: Product: 802.11n WLAN Adapter
[    2.433023] usb 1-1.4: Manufacturer: Realtek
[    2.437500] usb 1-1.4: SerialNumber: 00e04c000001
[    2.782209] omap_i2c 4802a000.i2c: timeout waiting for bus ready
[    2.788640] rtc-pcf8523: probe of 1-0068 failed with error -110
[    2.794926] omap_i2c 4802a000.i2c: bus 1 rev0.11 at 400 kHz
[    2.862235] davinci_mdio 4a101000.mdio: davinci mdio revision 1.6
[    2.868644] davinci_mdio 4a101000.mdio: detected phy mask fffffffe
[    2.878284] libphy: 4a101000.mdio: probed
[    2.882576] davinci_mdio 4a101000.mdio: phy[0]: device 4a101000.mdio:00, driver Atheros 8035 ethernet
[    2.893334] cpsw 4a100000.ethernet: Detected MACID = b0:d5:cc:f1:b4:c2
[    2.903433] hctosys: unable to open rtc device (rtc0)
[    2.942472] EXT4-fs (mmcblk1p3): mounted filesystem with ordered data mode. Opts: (null)
[    2.951116] VFS: Mounted root (ext4 filesystem) readonly on device 179:11.
[    2.963019] devtmpfs: mounted
[    2.966637] Freeing unused kernel memory: 276K (c069f000 - c06e4000)
INIT: version 2.88 booting
[    3.326781] EXT4-fs (mmcblk1p5): mounted filesystem with ordered data mode. Opts: (null)
[    3.342130] EXT4-fs (mmcblk1p6): mounted filesystem with ordered data mode. Opts: (null)
Starting udev
udev: Not using udev cache because of changes detected in the following files:
udev:     /proc/version /proc/cmdline /proc/devices
udev:     lib/udev/rules.d/* etc/udev/rules.d/*
udev: The udev cache will be regenerated. To identify the detected changes,
udev: compare the cached sysconf at   /etc/udev/cache.data
udev: against the current sysconf at  /dev/shm/udev.cache
[    3.591838] udevd[680]: starting version 182
[    4.148361] cfg80211: Calling CRDA to update world regulatory domain
[    4.541629] RTL871X: module init start
[    4.545686] RTL871X: rtl8723bu v4.3.6.11_12942.20141204_BTCOEX20140507-4E40
[    4.553004] RTL871X: rtl8723bu BT-Coex version = BTCOEX20140507-4E40
[    7.303915] cfg80211: Calling CRDA to update world regulatory domain
[    7.831303] RTL871X: rtw_ndev_init(wlan0)
[    7.838445] usbcore: registered new interface driver rtl8723bu
[    7.844634] RTL871X: module init ret=0
[    8.316933] EXT4-fs (mmcblk1p3): re-mounted. Opts: data=ordered
bootlogd: cannot allocate pseudo tty: No such file or directory
[    8.469522] random: dd urandom read with 105 bits of entropy available
Populating dev cache
hwclock: can't open '/dev/misc/rtc': No such file or directory
Sun Sep 18 10:39:09 UTC 2016
hwclock: can't open '/dev/misc/rtc': No such file or directory
Starting watchdog
[    9.566501] watchdog watchdog0: watchdog did not stop!
[   10.452378] cfg80211: Calling CRDA to update world regulatory domain
INIT: Entering runlevel: 5
Configuring network interfaces... [   11.271448] net eth0: initializing cpsw version 1.12 (0)
[   11.352750] net eth0: phy found : id is : 0x4dd072
[   11.357931] libphy: PHY 4a101000.mdio:01 not found
[   11.362990] net eth0: phy 4a101000.mdio:01 not found on slave 1
[   11.375101] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
udhcpc (v1.23.2) started
Sending discover...
[   13.602272] cfg80211: Calling CRDA to update world regulatory domain
Sending discover...
[   16.752334] cfg80211: Calling CRDA to update world regulatory domain
Sending discover...
[   19.902264] cfg80211: Calling CRDA to update world regulatory domain
No lease, forking to background
[   20.614254] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
done.
Starting system message bus: Setting up watches.
Watches established.
/var/run/dbus/ CREATE system_bus_socket
hwclock: can't open '/dev/misc/rtc': No such file or directory
Starting syslogd/klogd: done
Starting php-fpm [   21.025410] random: nonblocking pool is initialized
[   23.052403] cfg80211: Calling CRDA to update world regulatory domain
 done
Starting Connection Manager
Starting Hiawatha Web Server: hiawatha.
Starting crond: OK
dbus[1410]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
Checking available software versions...
dbus[1410]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
[   24.781949] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
Starting simple-upnpd

beaglebone login: [   26.202402] cfg80211: Calling CRDA to update world regulatory domain

beaglebone login: root
[   29.352364] cfg80211: Calling CRDA to update world regulatory domain
Last login: Sun Sep 18 10:38:37 +0000 2016 on /dev/ttyO0.
[   33.712058] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   33.719391] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   34.103828] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   34.111086] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   35.652573] cfg80211: Calling CRDA to update world regulatory domain
root@beaglebone:~# connmanctl
[   38.802331] cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
connmanctl> enable wifi
connmanctl> 
[   44.234751]
[   44.236337] =============================================
[   44.241994] [ INFO: possible recursive locking detected ]
[   44.247657] 4.1.15-venus #1 Tainted: G           O
[   44.252948] ---------------------------------------------
[   44.258604] connmand/1530 is trying to acquire lock:
[   44.263806]  (pmutex){+.+...}, at: [<bf109664>] usbctrl_vendorreq+0x7c/0x274 [8723bu]
[   44.272359]
[   44.272359] but task is already holding lock:
[   44.278473]  (pmutex){+.+...}, at: [<bf108454>] netdev_open+0x28/0x50 [8723bu]
[   44.286169]
[   44.286169] other info that might help us debug this:
[   44.293011]  Possible unsafe locking scenario:
[   44.293011]
[   44.299214]        CPU0
[   44.301772]        ----
[   44.304329]   lock(pmutex);
[   44.307261]   lock(pmutex);
[   44.310192]
[   44.310192]  *** DEADLOCK ***
[   44.310192]
[   44.316397]  May be due to missing lock nesting notation
[   44.316397]
[   44.323513] 2 locks held by connmand/1530:
[   44.327801]  #0:  (rtnl_mutex){+.+.+.}, at: [<c042c530>] devinet_ioctl+0xd0/0x7d4
[   44.335684]  #1:  (pmutex){+.+...}, at: [<bf108454>] netdev_open+0x28/0x50 [8723bu]
[   44.343823]
[   44.343823] stack backtrace:
[   44.348394] CPU: 0 PID: 1530 Comm: connmand Tainted: G           O    4.1.15-venus #1
[   44.356601] Hardware name: Generic AM33XX (Flattened Device Tree)
[   44.363014] [<c0014844>] (unwind_backtrace) from [<c0012994>] (show_stack+0x10/0x14)
[   44.371141] [<c0012994>] (show_stack) from [<c0067fe0>] (__lock_acquire+0x1454/0x1da0)
[   44.379445] [<c0067fe0>] (__lock_acquire) from [<c006922c>] (lock_acquire+0xac/0x12c)
[   44.387664] [<c006922c>] (lock_acquire) from [<c04bf4b4>] (mutex_lock_interruptible_nested+0x48/0x3bc)
[   44.397520] [<c04bf4b4>] (mutex_lock_interruptible_nested) from [<bf109664>] (usbctrl_vendorreq+0x7c/0x274 [8723bu])
[   44.408764] [<bf109664>] (usbctrl_vendorreq [8723bu]) from [<bf1389f0>] (usb_read8+0x30/0x3c [8723bu])
[   44.418690] [<bf1389f0>] (usb_read8 [8723bu]) from [<bf0db178>] (rtw_read8+0x18/0x1c [8723bu])
[   44.427877] [<bf0db178>] (rtw_read8 [8723bu]) from [<bf136eb0>] (rtl8723bu_hal_init+0x30/0xb4c [8723bu])
[   44.438006] [<bf136eb0>] (rtl8723bu_hal_init [8723bu]) from [<bf11c6b4>] (rtw_hal_init+0x18/0x154 [8723bu])
[   44.448393] [<bf11c6b4>] (rtw_hal_init [8723bu]) from [<bf10820c>] (_netdev_open+0x64/0x284 [8723bu])
[   44.458221] [<bf10820c>] (_netdev_open [8723bu]) from [<bf10845c>] (netdev_open+0x30/0x50 [8723bu])
[   44.467801] [<bf10845c>] (netdev_open [8723bu]) from [<c03c7d64>] (__dev_open+0xb8/0x11c)
[   44.476382] [<c03c7d64>] (__dev_open) from [<c03c7fe8>] (__dev_change_flags+0x94/0x144)
[   44.484777] [<c03c7fe8>] (__dev_change_flags) from [<c03c80b0>] (dev_change_flags+0x18/0x48)
[   44.493629] [<c03c80b0>] (dev_change_flags) from [<c042cb2c>] (devinet_ioctl+0x6cc/0x7d4)
[   44.502217] [<c042cb2c>] (devinet_ioctl) from [<c03adbec>] (sock_ioctl+0x1d8/0x2b0)
[   44.510251] [<c03adbec>] (sock_ioctl) from [<c011c39c>] (do_vfs_ioctl+0x3f0/0x5c0)
[   44.518191] [<c011c39c>] (do_vfs_ioctl) from [<c011c5a0>] (SyS_ioctl+0x34/0x5c)
[   44.525859] [<c011c5a0>] (SyS_ioctl) from [<c000f1e0>] (ret_fast_syscall+0x0/0x54)
[   45.223065] RTL871X: RTW_ADAPTIVITY_EN_AUTO, chplan:0x20, Regulation:0,0
[   45.230132] RTL871X: RTW_ADAPTIVITY_MODE_NORMAL
[   45.879243] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Enabled wifi
connmanctl> exit
[   47.733822] RTL871X: nolinked power save enter

root@beaglebone:~# reboot

Broadcast message from root@beaglebone (ttyO0) (Sun Sep 18 10:39:49 2016):
The system is going down for reboot NOW!
INIT: Sending processes the TERM signal
root@beaglebone:~# [   51.202492] RTL871X: RTW_ADAPTIVITY_EN_AUTO, chplan:0x20, Regulation:0,0
[   51.209553] RTL871X: RTW_ADAPTIVITY_MODE_NORMAL
[   51.761041] RTL871X: nolinked power save leave
[   53.833937] RTL871X: nolinked power save enter
INIT: Sending processes the KILL signal
Stopping simple-upnpd
Stopping system message bus
hwclock: can't open '/dev/misc/rtc': No such file or directory
Stopping syslogd/klogd: stopped syslogd (pid 1419)
stopped klogd (pid 1424)
done
Stopping Connection Manager
Stopping crond: OK
Gracefully shutting down php-fpm . done
Stopping Hiawatha Web Server: stopped /usr/sbin/hiawatha (pid 1534)
hiawatha.
Deconfiguring network interfaces... done.
Sending all processes the TERM signal...
Sending all processes the KILL signal...
Unmounting remote filesystems...
Deactivating swap...
Unmounting local filesystems...
[   65.163820] EXT4-fs (mmcblk1p3): re-mounted. Opts: data=ordered
Rebooting... [   67.290555] musb-hdrc musb-hdrc.1.auto: remove, state 1
[   67.296124] usb usb1: USB disconnect, device number 1
[   67.301424] usb 1-1: USB disconnect, device number 2
[   67.306648] usb 1-1.4: USB disconnect, device number 3

And that is where it was stuck again.

Also there is still the deadlock, but successful reboot, when rebooting without first enabling wifi. The message is a bit different though: the task holding the lock is no longer free_mlme_ap_info. Now it is rtw_free_stainfo. Makes sense I suppose since you fixed free_mlme_ap_info. See new log below.

I tried the old version again, to make sure this is no coincidence. And indeed, with old image the task holding the lock back to free_mlme_ap_info.

Log of not enabling wifi, and then reboot, with latest (bc9e782) version of rtl8723bu driver:

[  198.935016] usb 1-1.4: USB disconnect, device number 3
[  198.950221] ------------[ cut here ]------------
[  198.955395] WARNING: CPU: 0 PID: 2622 at /media/venusbuilds/wipbbbjethro/build/tmp-glibc/work-shared/beaglebone/kernel-source/net/wireless/core.c:778 wiphy_unregister+0x2b4/0x2b8 [cfg80211]()
[  198.973298] Modules linked in: 8723bu(O) ti_am335x_adc kfifo_buf industrialio cfg80211 rfkill ti_am335x_tsc ti_am335x_tscadc
[  198.985163] CPU: 0 PID: 2622 Comm: reboot Tainted: G           O    4.1.15-venus #1
[  198.993219] Hardware name: Generic AM33XX (Flattened Device Tree)
[  198.999640] [<c0014844>] (unwind_backtrace) from [<c0012994>] (show_stack+0x10/0x14)
[  199.007795] [<c0012994>] (show_stack) from [<c00326d0>] (warn_slowpath_common+0x84/0xb0)
[  199.016332] [<c00326d0>] (warn_slowpath_common) from [<c0032798>] (warn_slowpath_null+0x1c/0x24)
[  199.025658] [<c0032798>] (warn_slowpath_null) from [<bf015aa4>] (wiphy_unregister+0x2b4/0x2b8 [cfg80211])
[  199.036190] [<bf015aa4>] (wiphy_unregister [cfg80211]) from [<bf11a230>] (rtw_wdev_unregister+0x48/0x4c [8723bu])
[  199.047227] [<bf11a230>] (rtw_wdev_unregister [8723bu]) from [<bf1078bc>] (rtw_unregister_netdevs+0x38/0x64 [8723bu])
[  199.058560] [<bf1078bc>] (rtw_unregister_netdevs [8723bu]) from [<bf108ec8>] (rtw_dev_remove+0x1c/0x74 [8723bu])
[  199.069355] [<bf108ec8>] (rtw_dev_remove [8723bu]) from [<c0308bd4>] (usb_unbind_interface+0x7c/0x278)
[  199.079149] [<c0308bd4>] (usb_unbind_interface) from [<c02a942c>] (__device_release_driver+0x70/0xe4)
[  199.088838] [<c02a942c>] (__device_release_driver) from [<c02a94c0>] (device_release_driver+0x20/0x2c)
[  199.098617] [<c02a94c0>] (device_release_driver) from [<c02a8f18>] (bus_remove_device+0xdc/0x108)
[  199.107940] [<c02a8f18>] (bus_remove_device) from [<c02a629c>] (device_del+0x110/0x210)
[  199.116351] [<c02a629c>] (device_del) from [<c03067c4>] (usb_disable_device+0xa0/0x1e8)
[  199.124762] [<c03067c4>] (usb_disable_device) from [<c02fe134>] (usb_disconnect+0x74/0x280)
[  199.133537] [<c02fe134>] (usb_disconnect) from [<c02fe2d0>] (usb_disconnect+0x210/0x280)
[  199.142020] ---[ end trace 381b489ff2459a17 ]---
[  199.152936] RTL871X: rtw_ndev_uninit(wlan0)
[  199.171126]
[  199.172711] =============================================
[  199.178369] [ INFO: possible recursive locking detected ]
[  199.184032] 4.1.15-venus #1 Tainted: G        W  O
[  199.189323] ---------------------------------------------
[  199.194979] reboot/2622 is trying to acquire lock:
[  199.199999]  (&(plock)->rlock){+.....}, at: [<bf0faebc>] rtw_free_xmitframe_queue+0x18/0x58 [8723bu]
[  199.209906]
[  199.209906] but task is already holding lock:
[  199.216019]  (&(plock)->rlock){+.....}, at: [<bf0f6aac>] rtw_free_stainfo+0x44/0x360 [8723bu]
[  199.225071]
[  199.225071] other info that might help us debug this:
[  199.231913]  Possible unsafe locking scenario:
[  199.231913]
[  199.238116]        CPU0
[  199.240673]        ----
[  199.243231]   lock(&(plock)->rlock);
[  199.246982]   lock(&(plock)->rlock);
[  199.250733]
[  199.250733]  *** DEADLOCK ***
[  199.250733]
[  199.256937]  May be due to missing lock nesting notation
[  199.256937]
[  199.264053] 9 locks held by reboot/2622:
[  199.268160]  #0:  (reboot_mutex){+.+.+.}, at: [<c005139c>] SyS_reboot+0x90/0x1d8
[  199.275951]  #1:  (&dev->mutex){......}, at: [<c02a7a38>] device_shutdown+0x84/0x1ec
[  199.284100]  #2:  (&dev->mutex){......}, at: [<c02a7a48>] device_shutdown+0x94/0x1ec
[  199.292240]  #3:  (usb_bus_list_lock){+.+.+.}, at: [<c0303458>] usb_remove_hcd+0x98/0x1fc
[  199.300845]  #4:  (&dev->mutex){......}, at: [<c02fe100>] usb_disconnect+0x40/0x280
[  199.308896]  #5:  (&dev->mutex){......}, at: [<c02fe100>] usb_disconnect+0x40/0x280
[  199.316945]  #6:  (&dev->mutex){......}, at: [<c02fe100>] usb_disconnect+0x40/0x280
[  199.324994]  #7:  (&dev->mutex){......}, at: [<c02a94b8>] device_release_driver+0x18/0x2c
[  199.333592]  #8:  (&(plock)->rlock){+.....}, at: [<bf0f6aac>] rtw_free_stainfo+0x44/0x360 [8723bu]
[  199.343096]
[  199.343096] stack backtrace:
[  199.347665] CPU: 0 PID: 2622 Comm: reboot Tainted: G        W  O    4.1.15-venus #1
[  199.355690] Hardware name: Generic AM33XX (Flattened Device Tree)
[  199.362100] [<c0014844>] (unwind_backtrace) from [<c0012994>] (show_stack+0x10/0x14)
[  199.370226] [<c0012994>] (show_stack) from [<c0067fe0>] (__lock_acquire+0x1454/0x1da0)
[  199.378531] [<c0067fe0>] (__lock_acquire) from [<c006922c>] (lock_acquire+0xac/0x12c)
[  199.386753] [<c006922c>] (lock_acquire) from [<c04c1f14>] (_raw_spin_lock_bh+0x44/0x54)
[  199.395238] [<c04c1f14>] (_raw_spin_lock_bh) from [<bf0faebc>] (rtw_free_xmitframe_queue+0x18/0x58 [8723bu])
[  199.405699] [<bf0faebc>] (rtw_free_xmitframe_queue [8723bu]) from [<bf0f6ab8>] (rtw_free_stainfo+0x50/0x360 [8723bu])
[  199.416976] [<bf0f6ab8>] (rtw_free_stainfo [8723bu]) from [<bf0f9994>] (free_mlme_ap_info+0x3c/0x48 [8723bu])
[  199.427533] [<bf0f9994>] (free_mlme_ap_info [8723bu]) from [<bf108dac>] (rtw_usb_if1_deinit+0x34/0xa4 [8723bu])
[  199.438275] [<bf108dac>] (rtw_usb_if1_deinit [8723bu]) from [<bf108f14>] (rtw_dev_remove+0x68/0x74 [8723bu])
[  199.448669] [<bf108f14>] (rtw_dev_remove [8723bu]) from [<c0308bd4>] (usb_unbind_interface+0x7c/0x278)
[  199.458435] [<c0308bd4>] (usb_unbind_interface) from [<c02a942c>] (__device_release_driver+0x70/0xe4)
[  199.468106] [<c02a942c>] (__device_release_driver) from [<c02a94c0>] (device_release_driver+0x20/0x2c)
[  199.477867] [<c02a94c0>] (device_release_driver) from [<c02a8f18>] (bus_remove_device+0xdc/0x108)
[  199.487172] [<c02a8f18>] (bus_remove_device) from [<c02a629c>] (device_del+0x110/0x210)
[  199.495567] [<c02a629c>] (device_del) from [<c03067c4>] (usb_disable_device+0xa0/0x1e8)
[  199.503963] [<c03067c4>] (usb_disable_device) from [<c02fe134>] (usb_disconnect+0x74/0x280)
[  199.512722] [<c02fe134>] (usb_disconnect) from [<c02fe2d0>] (usb_disconnect+0x210/0x280)
[  199.524515] musb-hdrc musb-hdrc.1.auto: USB bus 1 deregistered
[  199.531148] udc musb-hdrc.0.auto: releasing 'musb-hdrc.0.auto'
[  199.538230] reboot: Restarting system

@mpvader
Copy link
Author

mpvader commented Sep 22, 2016

Hi. I've just rebuilt the whole thing, using @lwfinger's latest commit Fix unload problem With CONFIG_IOCTL_CFG80211 defined (4a134f7), and it now unloads and the device reboots again. thanks!

For me this issue can be closed now. And am curious if it is solved for you as well @sancloud.

@sancloud
Copy link

Using the latest it seems to be stable now at rebooting.
I have tried it in VE image and iOT image from bb org and they both reboot.

@mpvader mpvader closed this as completed Sep 26, 2016
mpvader added a commit to victronenergy/meta-victronenergy that referenced this issue Sep 30, 2016
Make sure to add this commit from upstream in the openembedded-core mete:
openembedded/openembedded-core@afcea61

It's needed to prevent these errors during compile:
WARNING: "wiphy_free" [/media/venusbuilds/wipbbbjethro/build/tmp-glibc/work/beaglebone-ve-linux-gnueabi/rtl8723bu/0.0-r0/git/8723bu.ko] undefined!
WARNING: "cfg80211_unlink_bss" [/media/venusbuilds/wipbbbjethro/build/tmp-glibc/work/beaglebone-ve-linux-gnueabi/rtl8723bu/0.0-r0/git/8723bu.ko] undefined!
[many more]

and later, when using the ko file, there errors in the bootlog:
[    4.554499] 8723bu: no symbol version for cfg80211_scan_done
[    4.560468] 8723bu: Unknown symbol cfg80211_scan_done (err -22)
...
many more, resulting in module not loading unless doing a manual modprobe -f

OPEN ISSUES
0) I added lib80211 to the defconfig at some point while trying to fix above
   issue. Probably isn't needed anymore. Todo: test & remove

1) Replace the hack in the rtl8723bu Makefile with something proper

2) Reboot doesn't work
   lwfinger/rtl8723bu#36

3) Kernel deadlocks right after boot:
[...]
[    3.544110] udevd[677]: starting version 182
[    4.125070] cfg80211: Calling CRDA to update world regulatory domain
[    4.499920] RTL871X: module init start
[    4.503973] RTL871X: rtl8723bu v4.3.6.11_12942.20141204_BTCOEX20140507-4E40
[    4.511273] RTL871X: rtl8723bu BT-Coex version = BTCOEX20140507-4E40
[    7.276123] cfg80211: Calling CRDA to update world regulatory domain
[    7.816563] RTL871X: rtw_ndev_init(wlan0)
[    7.823760] usbcore: registered new interface driver rtl8723bu
[    7.829887] RTL871X: module init ret=0
[    8.275916] EXT4-fs (mmcblk1p3): re-mounted. Opts: data=ordered
bootlogd: cannot allocate pseudo tty: No such file or directory
[    8.419817] random: dd urandom read with 105 bits of entropy available
Populating dev cache
[   10.432973] cfg80211: Calling CRDA to update world regulatory domain
hwclock: can't open '/dev/misc/rtc': No such file or directory
Thu Sep 15 23:48:31 UTC 2016
hwclock: can't open '/dev/misc/rtc': No such file or directory
Starting watchdog
[   11.915814] watchdog watchdog0: watchdog did not stop!
[   13.582859] cfg80211: Calling CRDA to update world regulatory domain
[   14.169740] random: nonblocking pool is initialized
update-rc.d: /etc/init.d/run-postinsts exists during rc.d purge (continuing)
 Removing any system startup links for run-postinsts ...
  /etc/rcS.d/S99run-postinsts
INIT: Entering runlevel: 5
Configuring network interfaces... [   14.520549] net eth0: initializing cpsw version 1.12 (0)
[   14.603248] net eth0: phy found : id is : 0x4dd072
[   14.608427] libphy: PHY 4a101000.mdio:01 not found
[   14.613487] net eth0: phy 4a101000.mdio:01 not found on slave 1
[   14.625689] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
udhcpc (v1.23.2) started
Sending discover...
[   16.732824] cfg80211: Calling CRDA to update world regulatory domain
Sending discover...
[   19.882724] cfg80211: Calling CRDA to update world regulatory domain
Sending discover...
[   23.032729] cfg80211: Calling CRDA to update world regulatory domain
No lease, forking to background
[   23.865391] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
done.
Starting system message bus: Setting up watches.
Watches established.
/var/run/dbus/ CREATE system_bus_socket
hwclock: can't open '/dev/misc/rtc': No such file or directory
Starting syslogd/klogd: done
Starting php-fpm [   25.190096] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   25.197402] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   25.991495] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   25.998758] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   26.182841] cfg80211: Calling CRDA to update world regulatory domain
 done
Starting Connection Manager
Starting Hiawatha Web Server: [   26.981252] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   26.988575] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
hiawatha.
dbus[1832]: [system] Activating service name='fi.w1.wpa_supplicant1' (using servicehelper)
Starting crond: dbus[1832]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
OK
[   27.518031]
[   27.519624] =============================================
[   27.525281] [ INFO: possible recursive locking detected ]
[   27.530944] 4.1.15-venus #1 Tainted: G           O
[   27.536236] ---------------------------------------------
[   27.541892] connmand/1959 is trying to acquire lock:
[   27.547094]  (pmutex){+.+...}, at: [<bf0ef664>] usbctrl_vendorreq+0x7c/0x274 [8723bu]
[   27.555649]
[   27.555649] but task is already holding lock:
[   27.561764]  (pmutex){+.+...}, at: [<bf0ee454>] netdev_open+0x28/0x50 [8723bu]
[   27.569468]
[   27.569468] other info that might help us debug this:
[   27.576311]  Possible unsafe locking scenario:
[   27.576311]
[   27.582516]        CPU0
[   27.585075]        ----
[   27.587632]   lock(pmutex);
[   27.590565]   lock(pmutex);
[   27.593497]
[   27.593497]  *** DEADLOCK ***
[   27.593497]
[   27.599704]  May be due to missing lock nesting notation
[   27.599704]
[   27.606822] 2 locks held by connmand/1959:
[   27.611111]  #0:  (rtnl_mutex){+.+.+.}, at: [<c042d050>] devinet_ioctl+0xd0/0x7d4
[   27.618996]  #1:  (pmutex){+.+...}, at: [<bf0ee454>] netdev_open+0x28/0x50 [8723bu]
[   27.627136]
[   27.627136] stack backtrace:
[   27.631706] CPU: 0 PID: 1959 Comm: connmand Tainted: G           O    4.1.15-venus #1
[   27.639914] Hardware name: Generic AM33XX (Flattened Device Tree)
[   27.646326] [<c0014844>] (unwind_backtrace) from [<c0012994>] (show_stack+0x10/0x14)
[   27.654455] [<c0012994>] (show_stack) from [<c0067fe0>] (__lock_acquire+0x1454/0x1da0)
[   27.662759] [<c0067fe0>] (__lock_acquire) from [<c006922c>] (lock_acquire+0xac/0x12c)
[   27.670979] [<c006922c>] (lock_acquire) from [<c04bffd4>] (mutex_lock_interruptible_nested+0x48/0x3bc)
[   27.680833] [<c04bffd4>] (mutex_lock_interruptible_nested) from [<bf0ef664>] (usbctrl_vendorreq+0x7c/0x274 [8723bu])
[   27.692079] [<bf0ef664>] (usbctrl_vendorreq [8723bu]) from [<bf11e9f0>] (usb_read8+0x30/0x3c [8723bu])
[   27.702011] [<bf11e9f0>] (usb_read8 [8723bu]) from [<bf0c1178>] (rtw_read8+0x18/0x1c [8723bu])
[   27.711204] [<bf0c1178>] (rtw_read8 [8723bu]) from [<bf11ceb0>] (rtl8723bu_hal_init+0x30/0xb4c [8723bu])
[   27.721338] [<bf11ceb0>] (rtl8723bu_hal_init [8723bu]) from [<bf1026b4>] (rtw_hal_init+0x18/0x154 [8723bu])
[   27.731727] [<bf1026b4>] (rtw_hal_init [8723bu]) from [<bf0ee20c>] (_netdev_open+0x64/0x284 [8723bu])
[   27.741561] [<bf0ee20c>] (_netdev_open [8723bu]) from [<bf0ee45c>] (netdev_open+0x30/0x50 [8723bu])
[   27.751143] [<bf0ee45c>] (netdev_open [8723bu]) from [<c03c8884>] (__dev_open+0xb8/0x11c)
[   27.759726] [<c03c8884>] (__dev_open) from [<c03c8b08>] (__dev_change_flags+0x94/0x144)
[   27.768123] [<c03c8b08>] (__dev_change_flags) from [<c03c8bd0>] (dev_change_flags+0x18/0x48)
[   27.776978] [<c03c8bd0>] (dev_change_flags) from [<c042d64c>] (devinet_ioctl+0x6cc/0x7d4)
[   27.785559] [<c042d64c>] (devinet_ioctl) from [<c03ae70c>] (sock_ioctl+0x1d8/0x2b0)
[   27.793593] [<c03ae70c>] (sock_ioctl) from [<c011c39c>] (do_vfs_ioctl+0x3f0/0x5c0)
[   27.801533] [<c011c39c>] (do_vfs_ioctl) from [<c011c5a0>] (SyS_ioctl+0x34/0x5c)
[   27.809201] [<c011c5a0>] (SyS_ioctl) from [<c000f1e0>] (ret_fast_syscall+0x0/0x54)
Checking available software versions...
[   28.191668] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
Starting simple-upnpd
[   31.095134] RTL871X: RTW_ADAPTIVITY_EN_AUTO, chplan:0x20, Regulation:0,0
[   31.102220] RTL871X: RTW_ADAPTIVITY_MODE_NORMAL
[   32.523712] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   32.536569] cfg80211: Calling CRDA to update world regulatory domain
[   32.604106] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   32.611164] c_can_platform 481d0000.can: obtain a copy of previously claimed pinctrl
[   32.619469] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   33.212819] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
[   33.220096] c_can_platform 481d0000.can: obtain a copy of previously claimed pinctrl
[   33.291001] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[   33.704635] RTL871X: nolinked power save enter
[   39.083257] RTL871X: RTW_ADAPTIVITY_EN_AUTO, chplan:0x20, Regulation:0,0
[   39.090326] RTL871X: RTW_ADAPTIVITY_MODE_NORMAL
[   40.204562] RTL871X: nolinked power save leave
[   40.425420] RTL871X: rtw_set_802_11_connect(wlan0)  fw_state=0x00000008
[   40.432584] cfg80211: Calling CRDA to update world regulatory domain
[   40.498385] RTL871X: start auth
[   40.503755] RTL871X: auth success, start assoc
[   40.512793] RTL871X: rtw_cfg80211_indicate_connect(wlan0) BSS not found !!
[   40.520058] RTL871X: assoc success
[   40.524101] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   40.956425] RTL871X: send eapol packet
[   40.978771] RTL871X: send eapol packet
[   40.994451] RTL871X: set pairwise key camid:4, addr:98:fc:11:ae:b5:04, kid:0, type:AES
bgscan simple: Failed to enable signal strength monitoring
[   41.024333] RTL871X: set group key camid:5, addr:98:fc:11:ae:b5:04, kid:1, type:AES
[   43.582737] cfg80211: Calling CRDA to update world regulatory domain
[   46.732739] cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
mpvader added a commit to victronenergy/meta-victronenergy that referenced this issue Oct 9, 2016
Make sure to add this commit from upstream to openembedded-core:
openembedded/openembedded-core@afcea61

It's needed to prevent these errors during compile:
WARNING: "wiphy_free" [/media/venusbuilds/wipbbbjethro/build/tmp-glibc/work/beaglebone-ve-linux-gnueabi/rtl8723bu/0.0-r0/git/8723bu.ko] undefined!
WARNING: "cfg80211_unlink_bss" [/media/venusbuilds/wipbbbjethro/build/tmp-glibc/work/beaglebone-ve-linux-gnueabi/rtl8723bu/0.0-r0/git/8723bu.ko] undefined!
[many more]

And, without that upstream commit, there are also these errors in the bootlog:
[    4.554499] 8723bu: no symbol version for cfg80211_scan_done
[    4.560468] 8723bu: Unknown symbol cfg80211_scan_done (err -22)
[many more]
resulting in module not loading unless doing a manual modprobe -f

Remaining issues:
1) there is a kernel deadlock warning while the driver is loaded.
   lwfinger/rtl8723bu#40

2) there is some error message during driver unload/reboot. Less important,
   and less bad than it used to be: the device would get stuck, but that is
   fixed already:
   lwfinger/rtl8723bu#36
mpvader added a commit to victronenergy/meta-victronenergy that referenced this issue Oct 10, 2016
Also add this commit from upstream to openembedded-core:
openembedded/openembedded-core@afcea61

It is needed to prevent these errors during compile:
WARNING: "wiphy_free" [/media/venusbuilds/wipbbbjethro/build/tmp-glibc/work/beaglebone-ve-linux-gnueabi/rtl8723bu/0.0-r0/git/8723bu.ko] undefined!
WARNING: "cfg80211_unlink_bss" [/media/venusbuilds/wipbbbjethro/build/tmp-glibc/work/beaglebone-ve-linux-gnueabi/rtl8723bu/0.0-r0/git/8723bu.ko] undefined!
[many more]

And, without that upstream commit, there are also these errors in the bootlog:
[    4.554499] 8723bu: no symbol version for cfg80211_scan_done
[    4.560468] 8723bu: Unknown symbol cfg80211_scan_done (err -22)
[many more]
resulting in module not loading unless doing a manual modprobe -f

There are two harmless visible kernel deadlock warnings:

1) during loading of the driver. Harmless according to lwfinger, the maintainer:
   lwfinger/rtl8723bu#40

2) during unloading of the driver. Less bad than it used to be: the device was
   getting stuck during unload, but that has been fixed:
   lwfinger/rtl8723bu#36
mpvader added a commit to victronenergy/meta-victronenergy that referenced this issue Oct 14, 2016
Also add this commit from upstream to openembedded-core:
openembedded/openembedded-core@afcea61
Needed to prevent warnings exactly like mentioned in that commit message.

There are -still- two harmless visible kernel deadlock warnings:

1) when loading of the driver. Which is according to the maintainer, lwfinger,
   harmless:
   lwfinger/rtl8723bu#40

2) when unloading of the driver. Less bad than it used to be: the device was
   getting stuck during unload, but that has been fixed:
   lwfinger/rtl8723bu#36
jhofstee pushed a commit to victronenergy/meta-victronenergy that referenced this issue Oct 20, 2016
Also add this commit from upstream to openembedded-core:
openembedded/openembedded-core@afcea61
Needed to prevent warnings exactly like mentioned in that commit message.

There are -still- two harmless visible kernel deadlock warnings:

1) when loading of the driver. Which is according to the maintainer, lwfinger,
   harmless:
   lwfinger/rtl8723bu#40

2) when unloading of the driver. Less bad than it used to be: the device was
   getting stuck during unload, but that has been fixed:
   lwfinger/rtl8723bu#36
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants