WL1831MOD: module bluetooth miss connection after several times of bluetoothctl scan on/off or power on/off

Sophie Hu

Part Number: WL1831MOD
Other Parts Discussed in Thread: WL1831, AM3352

Hi,

This is a bluetooth issue but I can only choose Wi-Fi forum when I enter part number WL1831MOD.
Please help to move to the correct forum if this is incorrect.

We have our own custom AM3352 board with WL1831 module. Basically wifi function and bluetooth function are OK. Making bluetooth to receive beacon is OK.

However, when we try to launch "bluetoothctl" and send command "scan on", it is OK for some boards and fails for some board.
And then we try to "scan off"-> "scan on", or "power down" -> "power on", for several times, the first time OK board is fail and the kernel message shows hci command tx timeout.

2021-09-03_11-26-57.log shows fail for the first time to scan on.
2021-09-03_11-26-57.log

2021-09-03_15-08-39.log shows fail affer several scan off/on and power off/on.

2021-09-03_15-08-39.log

[Fri Sep 03 15:08:48.559 2021] 
[Fri Sep 03 15:08:48.562 2021] aaeon@SRG-3352C:~$ 
[Fri Sep 03 15:08:49.290 2021] aaeon@SRG-3352C:~$ ps -A
[Fri Sep 03 15:08:53.574 2021]   PID TTY          TIME CMD
[Fri Sep 03 15:08:53.576 2021]     1 ?        00:00:05 systemd
[Fri Sep 03 15:08:53.577 2021]     2 ?        00:00:00 kthreadd
[Fri Sep 03 15:08:53.577 2021]     3 ?        00:00:00 rcu_gp
[Fri Sep 03 15:08:53.578 2021]     4 ?        00:00:00 rcu_par_gp
[Fri Sep 03 15:08:53.578 2021]     5 ?        00:00:00 kworker/0:0-events
[Fri Sep 03 15:08:53.581 2021]     6 ?        00:00:00 kworker/0:0H-kblockd
[Fri Sep 03 15:08:53.582 2021]     7 ?        00:00:00 kworker/u2:0-events_unbound
[Fri Sep 03 15:08:53.583 2021]     8 ?        00:00:00 mm_percpu_wq
[Fri Sep 03 15:08:53.583 2021]     9 ?        00:00:00 ksoftirqd/0
[Fri Sep 03 15:08:53.584 2021]    10 ?        00:00:00 ktimersoftd/0
[Fri Sep 03 15:08:53.584 2021]    11 ?        00:00:00 rcu_preempt
[Fri Sep 03 15:08:53.584 2021]    12 ?        00:00:00 rcu_sched
[Fri Sep 03 15:08:53.584 2021]    13 ?        00:00:00 rcub/0
[Fri Sep 03 15:08:53.584 2021]    14 ?        00:00:00 rcuc/0
[Fri Sep 03 15:08:53.585 2021]    15 ?        00:00:00 kswork
[Fri Sep 03 15:08:53.587 2021]    16 ?        00:00:00 posixcputmr/0
[Fri Sep 03 15:08:53.588 2021]    17 ?        00:00:00 kdevtmpfs
[Fri Sep 03 15:08:53.588 2021]    18 ?        00:00:00 netns
[Fri Sep 03 15:08:53.588 2021]    19 ?        00:00:00 rcu_tasks_kthre
[Fri Sep 03 15:08:53.588 2021]    20 ?        00:00:00 kauditd
[Fri Sep 03 15:08:53.588 2021]    21 ?        00:00:00 irq/26-44e07000
[Fri Sep 03 15:08:53.589 2021]    22 ?        00:00:00 kworker/0:1-events_power_efficient
[Fri Sep 03 15:08:53.589 2021]    23 ?        00:00:00 irq/27-4804c000
[Fri Sep 03 15:08:53.589 2021]    24 ?        00:00:00 irq/28-481ac000
[Fri Sep 03 15:08:53.589 2021]    25 ?        00:00:00 irq/29-481ae000
[Fri Sep 03 15:08:53.590 2021]    26 ?        00:00:00 khungtaskd
[Fri Sep 03 15:08:53.590 2021]    27 ?        00:00:00 oom_reaper
[Fri Sep 03 15:08:53.590 2021]    28 ?        00:00:00 writeback
[Fri Sep 03 15:08:53.590 2021]    29 ?        00:00:00 kcompactd0
[Fri Sep 03 15:08:53.593 2021]    30 ?        00:00:00 ksmd
[Fri Sep 03 15:08:53.593 2021]    31 ?        00:00:00 crypto
[Fri Sep 03 15:08:53.594 2021]    32 ?        00:00:00 kintegrityd
[Fri Sep 03 15:08:53.594 2021]    33 ?        00:00:00 kblockd
[Fri Sep 03 15:08:53.594 2021]    34 ?        00:00:00 irq/20-49000000
[Fri Sep 03 15:08:53.594 2021]    35 ?        00:00:00 irq/22-49000000
[Fri Sep 03 15:08:53.594 2021]    36 ?        00:00:00 ata_sff
[Fri Sep 03 15:08:53.595 2021]    37 ?        00:00:00 edac-poller
[Fri Sep 03 15:08:53.595 2021]    38 ?        00:00:00 devfreq_wq
[Fri Sep 03 15:08:53.595 2021]    39 ?        00:00:00 watchdogd
[Fri Sep 03 15:08:53.595 2021]    40 ?        00:00:00 rpciod
[Fri Sep 03 15:08:53.595 2021]    41 ?        00:00:00 kworker/u3:0-hci0
[Fri Sep 03 15:08:53.596 2021]    42 ?        00:00:00 xprtiod
[Fri Sep 03 15:08:53.605 2021]    43 ?        00:00:00 kswapd0
[Fri Sep 03 15:08:53.606 2021]    44 ?        00:00:00 nfsiod
[Fri Sep 03 15:08:53.606 2021]    79 ?        00:00:00 kthrotld
[Fri Sep 03 15:08:53.606 2021]    80 ?        00:00:00 irq/55-48310000
[Fri Sep 03 15:08:53.606 2021]    81 ?        00:00:00 hwrng
[Fri Sep 03 15:08:53.607 2021]    82 ?        00:00:00 kworker/u2:1-phy0
[Fri Sep 03 15:08:53.607 2021]    83 ?        00:00:00 irq/35-mmc0
[Fri Sep 03 15:08:53.607 2021]    84 ?        00:00:00 irq/36-mmc1
[Fri Sep 03 15:08:53.607 2021]    85 ?        00:00:00 irq/37-mmc2
[Fri Sep 03 15:08:53.608 2021]    86 ?        00:00:00 mmc_complete
[Fri Sep 03 15:08:53.608 2021]    87 ?        00:00:00 kworker/0:1H-kblockd
[Fri Sep 03 15:08:53.608 2021]    88 ?        00:00:00 kworker/0:2-events
[Fri Sep 03 15:08:53.608 2021]    89 ?        00:00:00 irq/47-481a0000
[Fri Sep 03 15:08:53.625 2021]    90 ?        00:00:00 spi1
[Fri Sep 03 15:08:53.626 2021]    91 ?        00:00:00 irq/45-rtc0
[Fri Sep 03 15:08:53.626 2021]    92 ?        00:00:00 irq/46-rtc0
[Fri Sep 03 15:08:53.626 2021]    93 ?        00:00:00 53500000.aes-en
[Fri Sep 03 15:08:53.626 2021]    99 ?        00:00:00 irq/53-53100000
[Fri Sep 03 15:08:53.627 2021]   108 ?        00:00:00 ion_system_heap
[Fri Sep 03 15:08:53.627 2021]   109 ?        00:00:00 ipv6_addrconf
[Fri Sep 03 15:08:53.627 2021]   118 ?        00:00:00 irq/34-44e0b000
[Fri Sep 03 15:08:53.627 2021]   119 ?        00:00:00 irq/56-tps65217
[Fri Sep 03 15:08:53.627 2021]   121 ?        00:00:00 kworker/0:2H-mmc_complete
[Fri Sep 03 15:08:53.628 2021]   122 ?        00:00:00 jbd2/mmcblk1p3-
[Fri Sep 03 15:08:53.628 2021]   123 ?        00:00:00 ext4-rsv-conver
[Fri Sep 03 15:08:53.628 2021]   141 ?        00:00:01 systemd-journal
[Fri Sep 03 15:08:53.628 2021]   148 ?        00:00:00 kworker/u2:2-events_unbound
[Fri Sep 03 15:08:53.629 2021]   150 ?        00:00:00 kworker/0:3-events_power_efficient
[Fri Sep 03 15:08:53.629 2021]   160 ?        00:00:01 systemd-udevd
[Fri Sep 03 15:08:53.629 2021]   200 ?        00:00:00 irq/62-47400000
[Fri Sep 03 15:08:53.629 2021]   323 ?        00:00:00 irq/19-wkup_m3_
[Fri Sep 03 15:08:53.630 2021]   325 ?        00:00:00 irq/39-wkup_m3
[Fri Sep 03 15:08:53.630 2021]   330 ?        00:00:00 irq/49-4a100000
[Fri Sep 03 15:08:53.630 2021]   332 ?        00:00:00 irq/50-4a100000
[Fri Sep 03 15:08:53.630 2021]   344 ?        00:00:00 kworker/0:3H
[Fri Sep 03 15:08:53.630 2021]   345 ?        00:00:00 kworker/0:4H
[Fri Sep 03 15:08:53.631 2021]   367 ?        00:00:00 jbd2/mmcblk1p2-
[Fri Sep 03 15:08:53.631 2021]   368 ?        00:00:00 ext4-rsv-conver
[Fri Sep 03 15:08:53.644 2021]   395 ?        00:00:00 auditd
[Fri Sep 03 15:08:53.644 2021]   431 ?        00:00:00 irq/60-musb-hdr
[Fri Sep 03 15:08:53.644 2021]   433 ?        00:00:00 irq/61-musb-hdr
[Fri Sep 03 15:08:53.645 2021]   438 ?        00:00:00 kworker/0:4-memcg_kmem_cache
[Fri Sep 03 15:08:53.645 2021]   440 ?        00:00:00 systemd-logind
[Fri Sep 03 15:08:53.645 2021]   443 ?        00:00:00 avahi-daemon
[Fri Sep 03 15:08:53.645 2021]   444 ?        00:00:01 dbus-daemon
[Fri Sep 03 15:08:53.645 2021]   446 ?        00:00:02 NetworkManager
[Fri Sep 03 15:08:53.646 2021]   447 ?        00:00:00 avahi-daemon
[Fri Sep 03 15:08:53.646 2021]   448 ?        00:00:00 wpa_supplicant
[Fri Sep 03 15:08:53.646 2021]   449 ?        00:00:00 cron
[Fri Sep 03 15:08:53.646 2021]   450 ?        00:00:00 ModemManager
[Fri Sep 03 15:08:53.647 2021]   452 ?        00:00:01 syslog-ng
[Fri Sep 03 15:08:53.647 2021]   474 ?        00:00:00 polkitd
[Fri Sep 03 15:08:53.647 2021]   524 ?        00:00:00 chronyd
[Fri Sep 03 15:08:53.647 2021]   526 ?        00:00:00 chronyd
[Fri Sep 03 15:08:53.647 2021]   542 ?        00:00:02 fail2ban-server
[Fri Sep 03 15:08:53.648 2021]   546 ?        00:00:00 sshd
[Fri Sep 03 15:08:53.648 2021]   552 ttyGS0   00:00:00 login
[Fri Sep 03 15:08:53.648 2021]   553 ttyS0    00:00:00 agetty
[Fri Sep 03 15:08:53.648 2021]   554 tty1     00:00:00 agetty
[Fri Sep 03 15:08:53.648 2021]   564 ?        00:00:00 dnsmasq
[Fri Sep 03 15:08:53.648 2021]   567 ?        00:00:00 cfg80211
[Fri Sep 03 15:08:53.649 2021]   585 ?        00:00:00 irq/33-481aa000
[Fri Sep 03 15:08:53.649 2021]   605 ?        00:00:00 kworker/u3:1-hci0
[Fri Sep 03 15:08:53.649 2021]   606 ?        00:00:00 kworker/u3:2-hci0
[Fri Sep 03 15:08:53.649 2021]   612 ?        00:00:00 irq/64-4a101000
[Fri Sep 03 15:08:53.657 2021]   613 ?        00:00:00 ptp0
[Fri Sep 03 15:08:53.657 2021]   614 ?        00:00:00 hciattach
[Fri Sep 03 15:08:53.658 2021]   618 ?        00:00:00 bluetoothd
[Fri Sep 03 15:08:53.658 2021]   622 ?        00:00:00 irq/65-4a101000
[Fri Sep 03 15:08:53.658 2021]   623 ?        00:00:00 irq/30-44e09000
[Fri Sep 03 15:08:53.658 2021]   631 ?        00:00:00 wl12xx_wq
[Fri Sep 03 15:08:53.659 2021]   634 ?        00:00:00 irq/63-wl18xx
[Fri Sep 03 15:08:53.659 2021]   635 ?        00:00:00 irq/63-s-wl18xx
[Fri Sep 03 15:08:53.659 2021]   918 ?        00:00:00 exim4
[Fri Sep 03 15:08:53.659 2021]   923 ?        00:00:00 kworker/u2:3
[Fri Sep 03 15:08:53.659 2021]   930 ?        00:00:00 systemd
[Fri Sep 03 15:08:53.660 2021]   931 ?        00:00:00 (sd-pam)
[Fri Sep 03 15:08:53.660 2021]   940 ttyGS0   00:00:00 bash
[Fri Sep 03 15:08:53.660 2021]   964 ttyGS0   00:00:00 dmesg
[Fri Sep 03 15:08:53.660 2021]   966 ttyGS0   00:00:00 ps
[Fri Sep 03 15:08:53.660 2021] aaeon@SRG-3352C:~$ 
[Fri Sep 03 15:08:56.257 2021] aaeon@SRG-3352C:~$ clear
[Fri Sep 03 15:08:57.759 2021] aaeon@SRG-3352C:~$ bluetoothctl
[Fri Sep 03 15:09:01.062 2021] Agent registered
[Fri Sep 03 15:09:01.065 2021] [bluetooth]# power on
[Fri Sep 03 15:09:03.570 2021] [bluetooth]# Changing power on succeeded
[Fri Sep 03 15:09:03.573 2021] [bluetooth]# [CHG] Controller 40:BD:32:8D:42:38 Discoverable: no
[Fri Sep 03 15:09:04.340 2021] [bluetooth]# scan on
[Fri Sep 03 15:09:06.751 2021] [bluetooth]# Discovery started
[Fri Sep 03 15:09:06.754 2021] [bluetooth]# scan off
[Fri Sep 03 15:09:12.930 2021] [bluetooth]# Failed to stop discovery: org.bluez.Error.InProgress
[Fri Sep 03 15:09:12.937 2021] [bluetooth]# discoverable on
[Fri Sep 03 15:09:21.001 2021] [bluetooth]# Changing discoverable on succeeded
[Fri Sep 03 15:09:21.018 2021] [bluetooth]# [CHG] Controller 40:BD:32:8D:42:38 Discoverable: yes
[Fri Sep 03 15:09:21.040 2021] [bluetooth]# agent on
[Fri Sep 03 15:09:25.184 2021] Agent is already registered
[Fri Sep 03 15:09:25.184 2021] [bluetooth]# default-agent
[Fri Sep 03 15:09:28.663 2021] [bluetooth]# Default agent request successful
[Fri Sep 03 15:09:28.666 2021] [bluetooth]# scan on
[Fri Sep 03 15:09:30.355 2021] [bluetooth]# Discovery started
[Fri Sep 03 15:09:30.359 2021] [bluetooth]# [04-EA-56-E0-0D-7A]# [CHG] Device 04:EA:56:E0:0D:7A Connected: yes
[Fri Sep 03 15:09:56.307 2021] [04-EA-56-E0-0D-7A]# [CHG] Device 04:EA:56:E0:0D:7A Name: AA-LL00-2456
[Fri Sep 03 15:09:56.308 2021] [04-EA-56-E0-0D-7A]# [CHG] Device 04:EA:56:E0:0D:7A Alias: AA-LL00-2456
[Fri Sep 03 15:09:56.308 2021] [04-EA-56-E0-0D-7A]# Request confirmation
[Fri Sep 03 15:09:57.873 2021] [04-EA-56-E0-0D-7A]# [agent] Confirm passkey 543467 (yes/no): [CHG] Device 7E:45:54:64:23:F2 RSSI: -91
[Fri Sep 03 15:10:02.288 2021] [CHG] Device 7E:45:54:64:23:F2 TxPower: 8
[Fri Sep 03 15:10:02.290 2021] [CHG] Device 7E:45:54:64:23:F2 RSSI: -104
[Fri Sep 03 15:10:02.426 2021] [NEW] Device 19:1E:B6:95:F9:40 19-1E-B6-95-F9-40
[Fri Sep 03 15:10:02.832 2021] [CHG] Device 7E:45:54:64:23:F2 RSSI: -92
[Fri Sep 03 15:10:02.972 2021] [NEW] Device 00:07:32:00:27:07 SV87002707
[Fri Sep 03 15:10:04.589 2021] [NEW] Device 00:A0:50:A3:35:1D SV87A3351D
[Fri Sep 03 15:10:05.224 2021] [CHG] Device 00:07:32:00:23:04 RSSI: -96
[Fri Sep 03 15:10:06.785 2021] [CHG] Device 7E:45:54:64:23:F2 RSSI: -105
[Fri Sep 03 15:10:06.801 2021] [NEW] Device 00:07:32:00:25:71 SV87002571
[Fri Sep 03 15:10:07.488 2021] [CHG] Device A4:C3:F0:59:74:4F RSSI: -86
[Fri Sep 03 15:10:07.490 2021] [CHG] Device A4:C3:F0:59:74:4F TxPower: 12
[Fri Sep 03 15:10:09.038 2021] [CHG] Device 70:DD:A8:76:9B:FB RSSI: -77
[Fri Sep 03 15:10:10.409 2021] [CHG] Device 04:EA:56:E0:0D:7A RSSI: -90
[Fri Sep 03 15:10:10.409 2021] [CHG] Device 04:EA:56:E0:0D:7A TxPower: 12
[Fri Sep 03 15:10:10.410 2021] [CHG] Device 04:EA:56:E0:0D:7A UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
[Fri Sep 03 15:10:10.411 2021] [CHG] Device 04:EA:56:E0:0D:7A UUIDs: 0000110a-0000-1000-8000-00805f9b34fb
[Fri Sep 03 15:10:10.412 2021] [CHG] Device 04:EA:56:E0:0D:7A UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[Fri Sep 03 15:10:10.413 2021] [CHG] Device 04:EA:56:E0:0D:7A UUIDs: 0000110b-0000-1000-8000-00805f9b34fb
[Fri Sep 03 15:10:10.414 2021] [CHG] Device 04:EA:56:E0:0D:7A UUIDs: 0000111f-0000-1000-8000-00805f9b34fb
[Fri Sep 03 15:10:10.415 2021] [CHG] Device 04:EA:56:E0:0D:7A UUIDs: 0000111e-0000-1000-8000-00805f9b34fb
[Fri Sep 03 15:10:17.796 2021] [CHG] Device 00:07:32:00:25:71 RSSI: -110
[Fri Sep 03 15:10:18.456 2021] [CHG] Device 00:07:32:00:28:65 RSSI: -90
[Fri Sep 03 15:10:18.460 2021] [CHG] Device 00:07:32:00:28:65 ManufacturerData Key: 0x0131
[Fri Sep 03 15:10:18.461 2021] [CHG] Device 00:07:32:00:28:65 ManufacturerData Value:
[Fri Sep 03 15:10:18.461 2021]   23 01 00 00 00 00                                #.....          
[Fri Sep 03 15:10:18.822 2021] [CHG] Device 7E:45:54:64:23:F2 RSSI: -96
[Fri Sep 03 15:10:18.960 2021] [NEW] Device 00:07:32:00:25:15 SV87002515
[Fri Sep 03 15:10:20.077 2021] [CHG] Device 7E:45:54:64:23:F2 RSSI: -88
[Fri Sep 03 15:10:20.777 2021] [CHG] Device 00:07:32:00:25:71 RSSI: -92
[Fri Sep 03 15:10:22.066 2021] [NEW] Device 00:07:32:00:27:29 SV87002729
[Fri Sep 03 15:10:22.913 2021] [NEW] Device 00:07:32:00:28:91 SV87002891
[Fri Sep 03 15:10:27.866 2021] Request canceled
[Fri Sep 03 15:10:28.102 2021] [bluetooth]# [CHG] Device 04:EA:56:E0:0D:7A Connected: no
[Fri Sep 03 15:10:28.105 2021] [bluetooth]# [DEL] Device 04:EA:56:E0:0D:7A AA-LL00-2456
[Fri Sep 03 15:10:28.125 2021] [bluetooth]# [CHG] Device 19:1E:B6:95:F9:40 RSSI: -118
[Fri Sep 03 15:10:34.479 2021] [bluetooth]# [CHG] Device 19:1E:B6:95:F9:40 RSSI: -97
[Fri Sep 03 15:10:34.745 2021] [bluetooth]# [  377.022332] wlcore: down
[Fri Sep 03 15:10:37.766 2021] [  377.073734] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Sep 03 15:10:51.823 2021] [CHG] Device 00:07:32:00:25:71 RSSI: -110
[Fri Sep 03 15:10:51.823 2021] [bluetooth]# [CHG] Device 00:07:32:00:27:29 ManufacturerData Key: 0x0131
[Fri Sep 03 15:10:52.199 2021] [bluetooth]# [CHG] Device 00:07:32:00:27:29 ManufacturerData Value:
[Fri Sep 03 15:10:52.200 2021] [bluetooth]#   1c 01 00 00 00 00                                ......          
[Fri Sep 03 15:10:52.200 2021] [bluetooth]# [NEW] Device 04:EA:56:E0:0D:7A AA-LL00-2456
[Fri Sep 03 15:10:55.970 2021] [bluetooth]# [  410.755929] Bluetooth: hci0: last event is not cmd complete (0x00)
[Fri Sep 03 15:11:11.456 2021] [  410.756135] Bluetooth: hci0: Frame reassembly failed (-84)
[Fri Sep 03 15:11:11.457 2021] [  410.756166] Bluetooth: hci0: Frame reassembly failed (-84)
[Fri Sep 03 15:11:21.859 2021] [CHG] Device 00:07:32:00:29:48 RSSI: -99
[Fri Sep 03 15:11:21.859 2021] [bluetooth]# [DEL] Device 7E:45:54:64:23:F2 7E-45-54-64-23-F2
[Fri Sep 03 15:12:12.741 2021] [bluetooth]# [DEL] Device 03:10:83:2C:D8:68 03-10-83-2C-D8-68
[Fri Sep 03 15:12:12.767 2021] [bluetooth]# [DEL] Device 00:07:32:00:21:77 SV87002177
[Fri Sep 03 15:12:12.786 2021] [bluetooth]# [DEL] Device 00:07:32:00:28:65 SV87002865
[Fri Sep 03 15:12:12.803 2021] [bluetooth]# [DEL] Device 70:DD:A8:76:9B:FB OPPO Reno Z
[Fri Sep 03 15:12:12.821 2021] [bluetooth]# [DEL] Device A4:C3:F0:59:74:4F AA-LB23-2214N
[Fri Sep 03 15:12:12.845 2021] [bluetooth]# [DEL] Device 03:77:DB:8C:BF:BA 03-77-DB-8C-BF-BA
[Fri Sep 03 15:12:12.860 2021] [bluetooth]# [DEL] Device 58:75:D4:DE:AD:C6 58-75-D4-DE-AD-C6
[Fri Sep 03 15:12:12.861 2021] [bluetooth]# [DEL] Device 00:07:32:00:23:04 SV87002304
[Fri Sep 03 15:12:12.880 2021] [bluetooth]# [DEL] Device 00:07:32:00:29:48 SV87002948
[Fri Sep 03 15:12:12.894 2021] [bluetooth]# [DEL] Device 19:1E:B6:95:F9:40 19-1E-B6-95-F9-40
[Fri Sep 03 15:12:12.907 2021] [bluetooth]# [DEL] Device 00:07:32:00:27:07 SV87002707
[Fri Sep 03 15:12:12.923 2021] [bluetooth]# [DEL] Device 00:A0:50:A3:35:1D SV87A3351D
[Fri Sep 03 15:12:12.940 2021] [bluetooth]# [DEL] Device 00:07:32:00:25:71 SV87002571
[Fri Sep 03 15:12:12.953 2021] [bluetooth]# [DEL] Device 00:07:32:00:25:15 SV87002515
[Fri Sep 03 15:12:12.966 2021] [bluetooth]# [DEL] Device 00:07:32:00:27:29 SV87002729
[Fri Sep 03 15:12:12.979 2021] [bluetooth]# [DEL] Device 00:07:32:00:28:91 SV87002891
[Fri Sep 03 15:12:12.997 2021] [bluetooth]# [DEL] Device 04:EA:56:E0:0D:7A AA-LL00-2456
[Fri Sep 03 15:12:13.013 2021] [bluetooth]# [  498.616258] Bluetooth: hci0: command 0x0c1a tx timeout
[Fri Sep 03 15:12:39.333 2021] [CHG] Controller 40:BD:32:8D:42:38 Discoverable: no
[Fri Sep 03 15:12:39.333 2021] [bluetooth]# [  692.076747] wlcore: down
[Fri Sep 03 15:15:52.815 2021] [  692.125656] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Sep 03 15:21:07.746 2021] [ 1007.071161] wlcore: down
[Fri Sep 03 15:21:07.793 2021] [ 1007.122141] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Sep 03 15:22:08.722 2021] [bluetooth]# scan on
[Fri Sep 03 15:22:11.327 2021] [bluetooth]# Failed to start discovery: org.bluez.Error.InProgress
[Fri Sep 03 15:22:11.331 2021] [bluetooth]# [bluetooth]# default-agentscan off
[Fri Sep 03 15:22:19.708 2021] [bluetooth]# [ 1081.072965] Bluetooth: hci0: command 0x0402 tx timeout
[Fri Sep 03 15:22:21.755 2021] Failed to stop discovery: org.bluez.Error.InProgress
[Fri Sep 03 15:22:21.755 2021] [bluetooth]# [bluetooth]# [bluetooth]# default-agentagent ondefault-agentscan off
[Fri Sep 03 15:22:42.905 2021] [bluetooth]# Failed to stop discovery: org.bluez.Error.Failed
[Fri Sep 03 15:22:42.914 2021] [bluetooth]# default-agent
[Fri Sep 03 15:22:44.893 2021] [bluetooth]# Default agent request successful
[Fri Sep 03 15:22:44.901 2021] [bluetooth]# default-agentscan on
[Fri Sep 03 15:22:49.889 2021] [bluetooth]# Discovery started
[Fri Sep 03 15:22:49.897 2021] [bluetooth]# scan off
[Fri Sep 03 15:22:55.818 2021] [bluetooth]# Failed to stop discovery: org.bluez.Error.InProgress
[Fri Sep 03 15:22:55.824 2021] [bluetooth]# default-agentscan onff
[Fri Sep 03 15:23:01.661 2021] [bluetooth]# Failed to stop discovery: org.bluez.Error.Failed
[Fri Sep 03 15:23:01.669 2021] [bluetooth]# power onff
[Fri Sep 03 15:23:04.721 2021] [bluetooth]# [ 1126.061113] Bluetooth: hci0: command 0x0c1a tx timeout
[Fri Sep 03 15:23:08.757 2021] [ 1128.077112] Bluetooth: hci0: command 0x0402 tx timeout
[Fri Sep 03 15:23:08.798 2021] [bluetooth]# Changing power off succeeded
[Fri Sep 03 15:23:09.850 2021] [bluetooth]# [CHG] Controller 40:BD:32:8D:42:38 Powered: no
[Fri Sep 03 15:23:09.863 2021] [bluetooth]# [CHG] Controller 40:BD:32:8D:42:38 Discovering: no
[Fri Sep 03 15:23:09.872 2021] [bluetooth]# [bluetooth]# [bluetooth]# power on
[Fri Sep 03 15:23:14.273 2021] [bluetooth]# sca[ 1135.596996] Bluetooth: hci0: command 0x1003 tx timeout
[Fri Sep 03 15:23:16.326 2021] n on
[Fri Sep 03 15:23:17.816 2021] [bluetooth]# Failed to start discovery: org.bluez.Error.NotReady
[Fri Sep 03 15:23:17.823 2021] [bluetooth]# [ 1137.613202] Bluetooth: hci0: command 0x1001 tx timeout
[Fri Sep 03 15:23:20.311 2021] [ 1139.628875] Bluetooth: hci0: command 0x1009 tx timeout
[Fri Sep 03 15:23:21.509 2021] [bluetooth]# power off
[Fri Sep 03 15:23:22.380 2021] [bluetooth]# Changing power off succeeded
[Fri Sep 03 15:23:22.388 2021] [bluetooth]# power offdefault-agentpower offFailed to set power on: org.bluez.Error.Failed
[Fri Sep 03 15:23:24.452 2021] [bluetooth]# power ofn
[Fri Sep 03 15:23:25.406 2021] [bluetooth]# [bluetooth]# scn[ 1146.732739] Bluetooth: hci0: command 0x1003 tx timeout
[Fri Sep 03 15:23:28.002 2021] a on
[Fri Sep 03 15:23:29.321 2021] Invalid command in menu main: scna
[Fri Sep 03 15:23:29.321 2021] 
[Fri Sep 03 15:23:29.321 2021] Use "help" for a list of available commands in a menu.
[Fri Sep 03 15:23:29.321 2021] Use "menu <submenu>" if you want to enter any submenu.
[Fri Sep 03 15:23:29.321 2021] Use "back" if you want to return to menu main.
[Fri Sep 03 15:23:29.322 2021] [bluetooth]# [ 1148.748710] Bluetooth: hci0: command 0x1001 tx timeout
[Fri Sep 03 15:23:30.952 2021] sca[ 1150.764632] Bluetooth: hci0: command 0x1009 tx timeout
[Fri Sep 03 15:23:31.476 2021] n on
[Fri Sep 03 15:23:32.119 2021] [bluetooth]# Failed to start discovery: org.bluez.Error.NotReady
[Fri Sep 03 15:23:32.120 2021] [bluetooth]# scan on
[Fri Sep 03 15:23:34.801 2021] [bluetooth]# Failed to start discovery: org.bluez.Error.NotReady
[Fri Sep 03 15:23:34.812 2021] [bluetooth]# Failed to set power on: org.bluez.Error.Failed
[Fri Sep 03 15:23:35.465 2021] [bluetooth]# [ 1322.006091] wlcore: down
[Fri Sep 03 15:26:22.803 2021] [ 1322.058937] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Sep 03 15:31:37.852 2021] [ 1637.060100] wlcore: down
[Fri Sep 03 15:31:37.906 2021] [ 1637.114872] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Sep 03 15:36:52.861 2021] [ 1952.054387] wlcore: down
[Fri Sep 03 15:36:52.905 2021] [ 1952.102041] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Sep 03 15:42:07.851 2021] [ 2267.048949] wlcore: down
[Fri Sep 03 15:42:07.903 2021] [ 2267.102897] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[Fri Sep 03 15:47:22.816 2021] [ 2582.019229] wlcore: down
[Fri Sep 03 15:47:22.859 2021] [ 2582.067048] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready

Here is our schematic.

I have connected BT_UART_DBG to PC and launch WiLink Wireless Tools - Bluetooth Logger to check the log.
The board failed to scan on for first time: glog_2021_09_03_144936.csv

glog_2021_09_03_144936.csv

The board is OK to scan on for first time but fail after several scan off/on and power off/on:glog_2021_09_03_150513.csv
glog_2021_09_03_150513.csv

Please help to check where could cause this issue?

Besides, what is BT_EN pin exactly for?
I have try to pull down the pin, there's no response from bluetooth of WL1831 immediately.
But when I pull up the pin again, there's still no response from bluetooth of WL1831.
Can we trigger BT_EN pin as reset or sleep bluetooth of WL1831 or something?

Best Regards,
Sophie

over 2 years ago

0 Seong Kim over 2 years ago

TI__Mastermind 34570 points

Hi Sophie,

Are you using the latest BT Service Pack?
See Section 4 in the WL8 Getting Started Guide to ensure you're using the latest driver and stack. Are you using the BlueZ stack? We don't support the BlueZ stack if this is a SW issue.
When powering-up and shutting-down the device, is the correct sequence being followed? See Section 8.19.2 in the datasheet.
BT_EN pin used to enable the BT as the name suggests. It must be HIGH to enable it.
- Once BT EN is asserted to high the BT FW stored in ROM start to execute, during this time the RTS is driven high to prevent HCI transaction and not to interfere with device boot, once the FW finish the boot process RTS line goes low after approximately 100 mS.

BR,

Seong

0 Sophie Hu over 2 years ago in reply to Seong Kim

Prodigy 70 points

Hi Seong,

1. Yes we use the BT service pack as your link above, version 4.7.

2. When I want to check the stack, follow section4 of WL8 Getting Started Guide, I want to read the document:
The TI
Bluetopia Stack integration details are provided at "TI Bluetooth Stack for WL18xx - Getting Started
Guide".
But the document link is missing.
Can you provide me the document?

3. I will check the power sequence with hardware member.

Best Regards,
Sophie

0 Seong Kim over 2 years ago in reply to Sophie Hu

TI__Mastermind 34570 points

Hi Sophie,

For the Bluetooth Stack Guide, you can download it here.

BR,

Seong

0 Sophie Hu over 2 years ago

Prodigy 70 points

Hi Seong,

We use BlueZ stack, but it seems not a sw issue.
It seems that BT will no resposse anymore if we power off it.
If we only scan off and scan on, it still works well. (2021-09-09_16-34-35.log)
But when we power off and power on, it easily becomes no response. (2021-09-09_16-34-35.log and 2021-09-09_17-42-04.log)

Besides, there are some failed messages during communicating with BT (2021-09-09_17-42-04.log), like:
[Thu Sep 09 17:42:53.845 2021] [bluetooth]# [ 149.313413] Bluetooth: hci0: last event is not cmd complete (0x00)
[Thu Sep 09 17:42:53.909 2021] [ 149.313627] Bluetooth: hci0: Frame reassembly failed (-84)
[Thu Sep 09 17:42:53.916 2021] [ 149.313658] Bluetooth: hci0: Frame reassembly failed (-84)
Is there some problem with UART?

2021-09-09_16-34-35.log

2021-09-09_17-42-04.log

Best Regards,
Sophie

0 Seong Kim over 2 years ago in reply to Sophie Hu

TI__Mastermind 34570 points

Hi Sophie,

I don't think it is a UART issue as you are able to execute commands as shown in your logs.

Is the BT_EN low before you execute the software reset?

BR,

Seong