• State TI Thinks Resolved
  • Locked Locked
  • Replies 10 replies
  • Answers 3 answers
  • Subscribers 41 subscribers
  • Views 443 views
  • Users 0 members are here
Support feedback
Options
Options
Related

This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

WL1837MOD: st core driver sometimes does not write data into uart line

Sreejith S
Prodigy 130 points
Part Number: WL1837MOD
Other Parts Discussed in Thread: WL1837

Hi,

I am having a custom board with imx6 SoC. Running Android 8.0. For bluetooth HAL using the linaro hikey HAL.

Facing an issue that sometimes the "Bluetooth stopped" message popup comes. On analysing the bluetooth stack logs it seen that command_timed_out expiry is hitting as a response is not received for the android bluetooth stack for 2 seconds for the command send.

On analysing further at driver level it is seen that whenever this issue happens when st_int_enqueue is called its in ST_LL_ASLEEP_TO_AWAKE state and its queued in tx_waitq. But this never gets written to the uart line. Sharing below a dump of driver logs. Please help in understanding the issue.

(hci_tty): inside hci_tty_write (d13656c0, ae3650a4, 3, d0ccff80)
(hci_tty): start data..
<out<03 0c 00
(hci_tty):
..end data
(stc): 3 to be written
(stc): st_int_enqueue
(stll) : returning state 2
(stc): ST LL is AWAKE, sending normally
(stc): done st_int_enqueue
(stc): st_tx_wakeup
(stc): st_int_dequeue
(stc): st_int_write: count 3
(stc): st_int_dequeue
(stc): st_tty_wakeup
(stc): st_tx_wakeup
(stc): st_int_dequeue
configfs-gadget gadget: high-speed config #1: b
(stc): count 7 rx_state 0rx_count 0
(stc): len 4 room 1846(stc): st_send_frame(prot:4)
(hci_tty): @ st_receive(hci_tty): rx list que !empty
(stc): done st_int_recv
(stc): done st_tty_receive
(hci_tty): inside hci_tty_ioctl (d13656c0, 21531, ae36484c)
(hci_tty): returning 7
(hci_tty): inside hci_tty_read (d13656c0, ae184000, 7, d1c5bf80)
(hci_tty): total size read= 7
(hci_tty): inside hci_tty_write (d13656c0, beeff57b, 1, d0ccff80)
(hci_tty): start data..<out<01
(hci_tty):
..end data(stc): 1 to be written
(stc): st_int_enqueue(stll) : returning state 2
(stc): ST LL is AWAKE, sending normally(stc): done st_int_enqueue
(stc): st_tx_wakeup(stc): st_int_dequeue
(stc): st_int_write: count 1
(stc): st_tty_wakeup (stc): st_tx_wakeup
(stc): ST already sending(stc): st_int_dequeue
(stc): st_int_dequeue(stc): count 1 rx_state 0rx_count 0
(stll) :sleep indication recvd
(stll) :ll_device_want_to_sleep
(stll) :send_ll_cmd: writing 31
(stc): st_int_write: count 1
(stll) :use device tree data
(stll) : returning state 0
(stc): done st_int_recv
(stc): done st_tty_receive
(hci_tty): inside hci_tty_write (d13656c0, ae3650d4, 3, d0ccff80)
(hci_tty): start data..<out<05 10 00
(hci_tty):
..end data(stc): 3 to be written
(stc): st_int_enqueue(stll) : returning state 0
(stll) :send_ll_cmd: writing 32(stc): st_int_write: count 1
(stc): done st_int_enqueue(stc): st_tx_wakeup
(stc): st_int_dequeuehealthd: battery l=100 v=12205 t=26.5 h=2 st=5 c=0 fc=3865000 rc=3865000 cc=41 te=3932100 tf=3932100 chg=a
(hci_tty): inside hci_tty_write (d13656c0, beeff57b, 1, d0ccff80)
(hci_tty): start data..<out<01
(hci_tty):
..end data(stc): 1 to be written
(stc): st_int_enqueue(stll) : returning state 1
(stc): done st_int_enqueue(stc): st_tx_wakeup
(stc): st_int_dequeue(hci_tty): inside hci_tty_write (d13656c0, ae3650d4, 3, d0ccff80)
(hci_tty): start data..<out<5b fd 00 ------> this data is not written in uart line
(hci_tty):
..end data(stc): 3 to be written
(stc): st_int_enqueue(stll) : returning state 1
(stc): done st_int_enqueue(stc): st_tx_wakeup
(stc): st_int_dequeuelogd: logdr: UID=1002 GID=1002 PID=1047 n tail=5 logMask=8 pid=510 start=0ns timeout=0ns
logd: logdr: UID=1002 GID=1002 PID=1047 n tail=5 logMask=1 pid=510 start=0ns timeout=0ns
healthd: battery l=100 v=12205 t=26.5 h=2 st=5 c=0 fc=3865000 rc=3865000 cc=41 te=3932100 tf=3932100 chg=a
SYSWDG: active_prcs_cnt = 1, connectioncount = 2
logd: logdr: UID=1002 GID=1002 PID=1047 n tail=0 logMask=8 pid=510 start=0ns timeout=0ns
logd: logdr: UID=1002 GID=1002 PID=1047 n tail=0 logMask=1 pid=510 start=0ns timeout=0ns
init: Untracked pid 1047 exited with status 0
(hci_tty): inside hci_tty_release (d0b69ac0, d13656c0)
(stc): st_unregister: 4 (stc): remove_channel_from_table: id 4
(stc): st_unregister: 2 (stc): remove_channel_from_table: id 2
(stc): st_unregister: 3 (stc): remove_channel_from_table: id 3
(stc): all chnl_ids unregistered (stc): st_tty_flush_buffer
(stk) :use device tree data(stc): st_tty_flush_buffer
(stk) :ldisc_install = 0(stc): st_tty_flush_buffer
(stc): st_tty_flush_buffer (stc): st_tty_close

LOGCAT:

08-26 14:14:46.308 510 1043 I bt_core_module: module_start_up Starting module "controller_module"
08-26 14:14:46.308 265 265 I android.hardware.bluetooth@1.0.lotus: BluetoothHci::sendHciCommand
08-26 14:14:46.308 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely length = 1
08-26 14:14:46.308 265 265 E android.hardware.bluetooth-hci-hci_protocol: 1
08-26 14:14:46.308 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely transmitted_length = 1
08-26 14:14:46.308 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely length = 3
08-26 14:14:46.308 265 265 E android.hardware.bluetooth-hci-hci_protocol: 3
08-26 14:14:46.308 265 265 E android.hardware.bluetooth-hci-hci_protocol: c
08-26 14:14:46.308 265 265 E android.hardware.bluetooth-hci-hci_protocol: 0
08-26 14:14:46.309 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely transmitted_length = 3
08-26 14:14:46.415 265 1040 E : Read data from the notification FD
08-26 14:14:46.415 265 1040 E : Invoke the data ready callbacks if appropriate
08-26 14:14:46.415 265 1040 I android.hardware.bluetooth@1.0.lotus: BluetoothHci::initialize() IOCTL
08-26 14:14:46.426 265 1040 I android.hardware.bluetooth@1.0.lotus: BluetoothHci::initialize() READ
08-26 14:14:46.436 265 1040 I android.hardware.bluetooth@1.0.lotus: BluetoothHci::initialize() WRITE
08-26 14:14:46.436 265 1040 I : AsyncFdWatcher::ThreadRoutine select wait...
08-26 14:14:46.436 265 1040 E : Read data from the notification FD
08-26 14:14:46.436 265 1040 E : Invoke the data ready callbacks if appropriate
08-26 14:14:46.436 265 1040 I : AsyncFdWatcher::ThreadRoutine select wait...
08-26 14:14:46.436 265 1040 E : Read data from the notification FD
08-26 14:14:46.436 265 1040 E : Invoke the data ready callbacks if appropriate
08-26 14:14:46.436 265 1040 I : AsyncFdWatcher::ThreadRoutine select wait...
08-26 14:14:46.436 265 1040 E : Read data from the notification FD
08-26 14:14:46.436 265 1040 E : Invoke the data ready callbacks if appropriate
08-26 14:14:46.438 265 1040 I : AsyncFdWatcher::ThreadRoutine select wait...
08-26 14:14:46.438 265 265 I android.hardware.bluetooth@1.0.lotus: BluetoothHci::sendHciCommand
08-26 14:14:46.438 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely length = 1
08-26 14:14:46.438 265 265 E android.hardware.bluetooth-hci-hci_protocol: 1
08-26 14:14:46.507 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely transmitted_length = 1
08-26 14:14:46.507 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely length = 3
08-26 14:14:46.507 265 265 E android.hardware.bluetooth-hci-hci_protocol: 5
08-26 14:14:46.507 265 265 E android.hardware.bluetooth-hci-hci_protocol: 10
08-26 14:14:46.508 265 265 E android.hardware.bluetooth-hci-hci_protocol: 0
08-26 14:14:46.513 839 1038 W MediaScanner: Error opening directory '/oem/media/', skipping: No such file or directory.
08-26 14:14:46.538 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely transmitted_length = 3
08-26 14:14:46.538 265 265 E hw-IPCThreadState: binder thread pool (1 threads) starved for 101 ms
08-26 14:14:46.586 839 1038 V MediaScanner: pruneDeadThumbnailFiles... android.content.ContentProviderClient$CursorWrapperInner@2575a2f
08-26 14:14:46.587 839 1038 V MediaScanner: /pruneDeadThumbnailFiles... android.content.ContentProviderClient$CursorWrapperInner@2575a2f
08-26 14:14:48.540 510 579 E bt_hci : command_timed_out: 1 commands pending response
08-26 14:14:48.540 510 579 E bt_hci : command_timed_out: Waited 2102 ms for a response to opcode: 0x1005 *matches timer*
08-26 14:14:48.540 510 579 E bt_hci : command_timed_out: Size 3 Hex 05 10 00
08-26 14:14:48.540 510 579 E bt_hci : command_timed_out: requesting a firmware dump.
08-26 14:14:48.541 265 265 I android.hardware.bluetooth@1.0.lotus: BluetoothHci::sendHciCommand
08-26 14:14:48.541 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely length = 1
08-26 14:14:48.541 265 265 E android.hardware.bluetooth-hci-hci_protocol: 1
08-26 14:14:48.567 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely transmitted_length = 1
08-26 14:14:48.567 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely length = 3
08-26 14:14:48.567 265 265 E android.hardware.bluetooth-hci-hci_protocol: 5b
08-26 14:14:48.567 265 265 E android.hardware.bluetooth-hci-hci_protocol: fd
08-26 14:14:48.567 265 265 E android.hardware.bluetooth-hci-hci_protocol: 0
08-26 14:14:48.592 265 265 E android.hardware.bluetooth-hci-hci_protocol: WriteSafely transmitted_length = 3
08-26 14:14:48.592 510 579 E bt_hci : command_timed_out restarting the Bluetooth process.
08-26 14:14:48.863 510 575 V BluetoothAdapterState: PendingCommand - transient state(s): isBleTurningOn
08-26 14:14:48.863 510 575 D BluetoothAdapterState: Current state: PENDING_COMMAND, message: 101
08-26 14:14:48.863 510 575 E BluetoothAdapterState: Error enabling Bluetooth (enable timeout)

Regards,

Sreejith

  • 0
    TI__Mastermind 27080 points

    Humm.. If the data is not appearing on the UART lines, i wonder if the UART IP or related domains went into, 'sleep' mode. Can, you try disabling low power states and see if it helps to identify the issue.

    Thanks

  • 0 in reply to Hari Nagalla
    Prodigy 130 points

    Hi Hari,

    st_int_write is the wrapper which actually calls the tty write. But st_int_write is not getting called when this issue happens.

    Regards,

    Sreejith

  • 0 in reply to Sreejith S
    TI__Mastermind 27080 points

    Where, did you take the ST driver from? Can, you please point to the sources. 

    Thanks

  • 0 in reply to Hari Nagalla
    Prodigy 130 points

    Hi Hari,

    Kernel Version is 4.9.17. 

    As said earlier, using Android 8.0.0 release for the imx6 from nxp. Kernel version which comes with this is 4.9.17. Using the same ST driver which is part of this release.

    For tty_hci, have taken the below commit above this.

    Bluetooth: Add tty HCI driver


    tty_hci driver exposes a /dev/hci_tty character device node, that intends to
    emulate a generic /dev/ttyX device that would be used by the user-space
    Bluetooth stacks to send/receive data to/from the WL combo-connectivity
    chipsets.

    The device driver has no internal logic of its own to intrepret data & all
    such logic is handled by the user-space stack.

    Change-Id: Ifa3860bbc7e252af210fde710bce14143239b552
    Signed-off-by: Pavan Savoy <pavan_savoy@ti.com>
    [Fixed checkpatch warnings]
    Signed-off-by: Vishal Mahaveer <vishalm@ti.com>
    [Fixed checkpatch --strict warnings]
    Signed-off-by: Eyal Reizer <eyalr@ti.com>

    Regards,

    Sreejith

  • 0 in reply to Sreejith S
    TI__Genius 10550 points

    Hi Sreejith, 

    Can you please explain the failure scenario? Can you please give us the user actions on the device that led to this issue? 

    Also if possible please send us he following files - st_core.c, st_ll.c, st_kim.c? 

    from the debug logs it looks like the HCI port (dev/hci_tty) is getting closed. Please let us know if you observe the same. Can you access /dev/hci_tty after the issue occurs? 

    Regards, 

    Sudharshan K N

  • 0 in reply to Sudharshan KN
    Prodigy 130 points

    Hi Sudharsan,

    There is a bluetooth printer connected to the device and when there is continuous data transfer to the printer for a long time this issue happens randomly.

    For debugging this issue when I changed all the prints in drivers/misc/ti-st from pr_debug to pr_info so that it comes in dmesg, strangely this issue started occurring more frequently like during when bt is turned on or a scan is done.

    st_core.c, st_ll.c, st_kim.c these 3 files are same as 4.9.17 + hci_tty enabling commit as mentioned earlier.

    Yes when this issue occurs, android bt stack closes the HCI port and restarts the android bluetooth service which opens the HCI port again.

    Regards,

    Sreejith

  • 0 in reply to Sreejith S
    TI__Genius 10550 points

    Hi Sreejit, 

    Just to confirm are you using the shared trasport driver code from following location? https://android.googlesource.com/kernel/omap/+/refs/heads/android-beagle-x15-4.19/drivers/misc/ti-st/. 

    Also can you please send us the complete logs? 

    Regards, 

    Sudharshan K N

  • 0 in reply to Sudharshan KN
    TI__Genius 10550 points

    Hi Sreejith, 

    have you updated the BT patch to the latest one? If not i suggest to use the latest patch and retest again. You can download the latest FW patch from http://www.ti.com/tool/WL18XX-BT-SP. the file is locates in bt-wifi-firmware-util (https://android.googlesource.com/device/linaro/hikey/+/refs/tags/android-8.1.0_r69/bt-wifi-firmware-util/). Please locate the file on your target and replace the file. 

    Regards, 

    Sudharshan K N

  • 0 in reply to Sudharshan KN
    Prodigy 130 points

    Hi Sudharsan,

    Driver code is same as in the link you shared.

    Also tried with the latest firmware patch spv4.4, but still the issue is observed.

    Did a uart dump when this issue happens. It looks to be that wakeup_ind (0x32) is send to chip for waking up, but it is not acknowledged. So the driver is not sending the data because of this.

    10/23/2019 12:22:18.371  [COM9] - 04 0F 04 00 01 19 04

    10/23/2019 12:22:18.374 [COM10] - 19 04 0A 47 EE CA 2D 65 94 01 00 A0 9B

    10/23/2019 12:22:18.467  [COM9] - 30

    10/23/2019 12:22:18.485 [COM10] - 31

    10/23/2019 12:22:19.523  [COM9] - 32 04 3D 0E 47 EE CA 2D 65 94 0F 00 00 00 00 00 00 00 04 07 FF 00 47 EE CA 2D 65 94 4F 6E 65 50 6C 75 73 20 35 54 00 05 01 07 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 40 00 72 00 00 00 24 0E 0E 20 89 6D 00

    10/23/2019 12:22:19.542 [COM10] - 33

    10/23/2019 12:22:19.651  [COM9] - 30   ------------------- -> sleep_ind from wl1837

    10/23/2019 12:22:19.654 [COM10] - 01 31 32 00   ------- -> sleep_ack (0x31) and then wakeup_ind (0x32) from host to wl1837 for which there is no response

    10/23/2019 12:22:31.262  [COM9] - 00

    10/23/2019 12:22:31.275 [COM10] - 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

    10/23/2019 12:22:31.277  [COM9] - 00 00 00 00 00 00 00 00 00 00 00 00

    10/23/2019 12:22:31.323 [COM10] - 01 01 10 00

    10/23/2019 12:22:31.326  [COM9] - 04 0E 0C 01 01 10 00 06 00 00 06 0D 00 20 AC

    10/23/2019 12:22:31.403 [COM10] - 01 37 FE 02 08 20

    10/23/2019 12:22:31.405  [COM9] - 04 0E 04 01 37 FE 00

    10/23/2019 12:22:31.419 [COM10] - 01 03 FF 09 B2 77 03 20 04 0A 00 08 00

    10/23/2019 12:22:31.421  [COM9] - 04 0E 04 01 03 FF 00

    Regards,

    Sreejith

  • 0 in reply to Sreejith S
    TI__Genius 10550 points

    Hi Sreejith, 

    Thanks for sending the data 

    10/23/2019 12:22:19.654 [COM10] - 01 31 32 00   ------- -> sleep_ack (0x31) and then wakeup_ind (0x32) from host to wl1837 for which there is no response

    The 0x01 in the beginning here is erroneous. The 01 31 32 00 will be interpreted as an HCI command with opcode 0x3231 and payload length of 0x00. There is no valid HCI command with opcode 0x3231. So that will break the HCILL because the controller is still waiting for the valid ACK (0x31) and according to the host, it has sent the 0x31 ACK and a wakeup indication 0x32 after that. So the host is also waiting for an ACK.

    Can you please take a look if the 0x01 is coming from stack? 

    Regards, 

    Sudharshan K N