Hi Marcel, This is my 2nd patchset in my series of resolving a design flaw in hci_uart_tty_close() related to the proper closure of the Data Link protocol layer which can result in a kernel crash. The 3 patches in this patchset will unmask the design flaw in hci_uart_tty_close() and provide a partial fix. My future patchsets based on my original 1st patchset V2 can be discussed at a later date to get a complete fix. Previous Discussions ==================== Please refer to the discussion on my 1st patchset V3 that can be found here: https://www.spinics.net/lists/linux-bluetooth/msg70315.html You accepted the first 3 patches of my series of commits namely: Bluetooth: hci_ldisc: Add missing return in hci_uart_init_work() Bluetooth: hci_ldisc: Ensure hu->hdev set to NULL before freeing hdev Bluetooth: hci_ldisc: Add missing clear HCI_UART_PROTO_READY drivers/bluetooth/hci_ldisc.c | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) Please refer to the discussion on my 1st patchset V2 that can be found here: https://www.spinics.net/lists/linux-bluetooth/msg70183.html Please refer to the discussion on my 1st RFC patchset V1 that can be found here: https://www.spinics.net/lists/linux-bluetooth/msg70077.html Failure test case ================= Note this failure is probably reproducible on many series 3 and 4 kernels. Connect a UART based Bluetooth Radio Module via a USB to serial adaptor to a Linux PC running kernel v4.10.11. This module used the Data Link protocol called BCSP but that is not too important because the issue is common to all the Data Link protocols. If the Data Link protocol supports a retransmission procedure then the probability of a kernel crash is higher. Use the Bluez utility called btattach to try to use BCSP. Note the BCSP implementation is incomplete in the kernel so BCSP will not establish a connection with the Bluetooth Radio Module. However, this is ideal in exposing the design issue in hci_uart_tty_close() because BCSP performs retransmissions. I created this simple testcase script to trigger a kernel crash in approximately 10 minutes of running. #!/bin/bash let i=1 while [ true ] do echo "loop $i" ./btattach -B /dev/ttyUSB0 -P bcsp -r & sleep 5 echo "now killing..." killall btattach i=$(($i + 1)) done I got the following kernel crash after 78 loops. Here is a snippet of the dmesg log (dynamic debug used) leading up to the crash: Note BCSP is retransmitting during hci_uart_tty_close() which increases the probability of crashing. [ 2932.969451] hci_uart_tty_close: tty ffff8c015f11d400 [ 2932.969455] hci_uart_close: hdev ffff8c01e3ee4000 [ 2932.969458] hci_uart_flush: hdev ffff8c01e3ee4000 tty ffff8c015f11d400 [ 2932.969460] bcsp_flush: hu ffff8c01f0bca240 [ 2932.969465] hci_unregister_dev: ffff8c01e3ee4000 name hci1 bus 3 [ 2933.154206] bcsp_timed_event: hu ffff8c01f0bca240 retransmitting 2 pkts [ 2933.154231] hci_uart_tx_wakeup: [ 2933.154446] bcsp_prepare_pkt: We request packet no 0 to card [ 2933.154447] bcsp_prepare_pkt: Sending packet with seqno 0 [ 2933.154465] bcsp_prepare_pkt: We request packet no 0 to card [ 2933.154466] bcsp_prepare_pkt: Sending packet with seqno 1 [ 2933.410201] bcsp_timed_event: hu ffff8c01f0bca240 retransmitting 2 pkts [ 2933.410240] hci_uart_tx_wakeup: [ 2933.410307] bcsp_prepare_pkt: We request packet no 0 to card [ 2933.410308] bcsp_prepare_pkt: Sending packet with seqno 0 [ 2933.410321] bcsp_prepare_pkt: We request packet no 0 to card [ 2933.410322] bcsp_prepare_pkt: Sending packet with seqno 1 [ 2933.666198] bcsp_timed_event: hu ffff8c01f0bca240 retransmitting 2 pkts [ 2933.666225] hci_uart_tx_wakeup: < snipped: do not show all BCSP retransmissions that occur every 250ms > [ 2934.182902] Bluetooth: hci1 command 0x1001 tx timeout [ 2934.182916] hci_cmd_work: hci1 cmd_cnt 1 cmd queued 1 [ 2934.182920] hci_send_frame: hci1 type 1 len 3 [ 2934.182922] hci_uart_send_frame: hci1: type 1 len 3 [ 2934.182923] hci_uart_tx_wakeup: [ 2934.182928] bcsp_prepare_pkt: We request packet no 0 to card [ 2934.182929] bcsp_prepare_pkt: Sending packet with seqno 2 [ 2934.434214] bcsp_timed_event: hu ffff8c01f0bca240 retransmitting 3 pkts [ 2934.434217] hci_uart_tx_wakeup: [ 2934.434243] bcsp_prepare_pkt: We request packet no 0 to card [ 2934.434244] bcsp_prepare_pkt: Sending packet with seqno 0 [ 2934.434263] bcsp_prepare_pkt: We request packet no 0 to card [ 2934.434264] bcsp_prepare_pkt: Sending packet with seqno 1 [ 2934.434268] bcsp_prepare_pkt: We request packet no 0 to card [ 2934.434269] bcsp_prepare_pkt: Sending packet with seqno 2 [ 2934.690178] bcsp_timed_event: hu ffff8c01f0bca240 retransmitting 3 pkts [ 2934.690217] hci_uart_tx_wakeup: < snipped: do not show all BCSP retransmissions that occur every 250ms > [ 2936.226215] Bluetooth: hci1 command 0x1009 tx timeout [ 2936.226233] hci_cmd_work: hci1 cmd_cnt 1 cmd queued 0 [ 2936.226280] bcsp_prepare_pkt: We request packet no 0 to card [ 2936.226282] bcsp_prepare_pkt: Sending packet with seqno 0 [ 2936.226300] bcsp_prepare_pkt: We request packet no 0 to card [ 2936.226301] bcsp_prepare_pkt: Sending packet with seqno 1 [ 2936.226304] bcsp_prepare_pkt: We request packet no 0 to card [ 2936.226306] bcsp_prepare_pkt: Sending packet with seqno 2 [ 2936.482149] bcsp_timed_event: hu ffff8c01f0bca240 retransmitting 3 pkts [ 2936.482179] hci_uart_tx_wakeup: [ 2936.482259] bcsp_prepare_pkt: We request packet no 0 to card [ 2936.482261] bcsp_prepare_pkt: Sending packet with seqno 0 [ 2936.482280] bcsp_prepare_pkt: We request packet no 0 to card [ 2936.482281] bcsp_prepare_pkt: Sending packet with seqno 1 [ 2936.482285] bcsp_prepare_pkt: We request packet no 0 to card [ 2936.482286] bcsp_prepare_pkt: Sending packet with seqno 2 [ 2936.738141] bcsp_timed_event: hu ffff8c01f0bca240 retransmitting 3 pkts [ 2936.738179] hci_uart_tx_wakeup: < snipped: do not show all BCSP retransmissions that occur every 250ms > [ 2940.066125] hci_uart_tx_wakeup: [ 2940.066200] bcsp_prepare_pkt: We request packet no 0 to card [ 2940.066202] bcsp_prepare_pkt: Sending packet with seqno 0 [ 2940.066221] bcsp_prepare_pkt: We request packet no 0 to card [ 2940.066223] bcsp_prepare_pkt: Sending packet with seqno 1 [ 2940.066227] bcsp_prepare_pkt: We request packet no 0 to card [ 2940.066230] bcsp_prepare_pkt: Sending packet with seqno 2 [ 2940.322113] bcsp_timed_event: hu ffff8c01f0bca240 retransmitting 3 pkts [ 2940.322126] hci_uart_tx_wakeup: [ 2940.322147] hci_uart_close: hdev ffff8c01e3ee4000 [ 2940.322149] hci_uart_flush: hdev ffff8c01e3ee4000 tty ffff8c015f11d400 [ 2940.322164] hci_dev_do_close: hci1 ffff8c01e3ee4000 [ 2940.322335] hci_conn_params_clear_all: All LE connection parameters were removed [ 2940.322340] bcsp_close: hu ffff8c01f0bca240 [ 2940.322667] ftdi_set_termios: ftdi_sio ttyUSB0: Setting CS8 [ 2940.322686] BUG: unable to handle kernel NULL pointer dereference at 0000000000000044 [ 2940.322750] IP: _raw_spin_lock_irqsave+0x22/0x40 [ 2940.322779] PGD 0 [ 2940.383274] Oops: 0002 [#1] SMP [ 2940.384001] Modules linked in: hci_uart btqca xt_set ip_set_hash_ip ip_set nf_log_ipv4 nf_log_ipv6 nf_log_common xt_LOG ip6table_nat nf_nat_ipv6 xt_recent iptable_nat nf_nat_ipv4 ip6t_REJECT nf_reject_ipv6 xt_comment ip6table_mangle ipt_REJECT nf_reject_ipv4 xt_addrtype bridge stp llc xt_mark iptable_mangle xt_tcpudp iptable_raw nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_tftp xt_CT nf_nat_snmp_basic nf_conntrack_snmp nf_nat_sip nf_nat_pptp nf_nat_proto_gre ip6table_raw nf_nat_irc xt_multiport nf_nat_h323 nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ftp nf_nat_amanda nf_nat xt_conntrack nf_conntrack_sane nf_conntrack_tftp ts_kmp nf_conntrack_sip nf_conntrack_amanda nf_conntrack_pptp nf_conntrack_proto_gre nf_conntrack_netlink nfnetlink nf_conntrack_netbios_ns nf_conntrack_broadcast nf_conntrack_irc nf_conntrack_h323 [ 2940.388162] nf_conntrack_ftp nf_conntrack ip6table_filter ip6_tables iptable_filter ip_tables x_tables lockd grace ctr ccm af_packet bnep msr arc4 brcmsmac uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 cordic btusb btrtl ftdi_sio brcmutil btbcm videobuf2_core btintel mac80211 usbserial bluetooth intel_powerclamp videodev coretemp kvm_intel kvm media snd_hda_codec_hdmi snd_hda_codec_realtek cfg80211 snd_hda_codec_generic snd_hda_intel joydev snd_hda_codec iTCO_wdt irqbypass snd_hda_core toshiba_acpi sparse_keymap iTCO_vendor_support crc32c_intel bcma industrialio snd_hwdep snd_pcm psmouse toshiba_bluetooth snd_timer input_leds serio_raw mei_me rfkill ac e1000e snd thermal wmi shpchp intel_ips battery toshiba_haps soundcore fjes lpc_ich mei ptp pps_core tpm_tis tpm_tis_core tpm cpufreq_ondemand [ 2940.393216] cpufreq_conservative cpufreq_powersave acpi_cpufreq evdev nvram sunrpc sch_fq_codel ipv6 crc_ccitt autofs4 hid_generic usbhid hid sdhci_pci mmc_block sr_mod sdhci ehci_pci ehci_hcd mmc_core usbcore usb_common i915 video button i2c_algo_bit drm_kms_helper drm [ 2940.395473] CPU: 3 PID: 6669 Comm: kworker/3:1 Not tainted 4.10.11_pure #1 [ 2940.396606] Hardware name: TOSHIBA Satellite R630/Portable PC, BIOS Version 1.40 07/20/2010 [ 2940.397763] Workqueue: events hci_uart_write_work [hci_uart] [ 2940.399076] task: ffff8c01f2883600 task.stack: ffffb2a704d34000 [ 2940.400360] RIP: 0010:_raw_spin_lock_irqsave+0x22/0x40 [ 2940.401511] RSP: 0018:ffffb2a704d37da8 EFLAGS: 00010046 [ 2940.402660] RAX: 0000000000000000 RBX: 0000000000000296 RCX: ffff8c01f2883600 [ 2940.403829] RDX: 0000000000000001 RSI: ffff8c01f7cd8ba0 RDI: 0000000000000044 [ 2940.404995] RBP: ffffb2a704d37db0 R08: ffff8c01f7cd8b80 R09: 00000000000001f9 [ 2940.406157] R10: 000002ac98e2f8d0 R11: 0000000000000001 R12: 0000000000000030 [ 2940.407317] R13: 0000000000000044 R14: 0000000000000030 R15: ffff8c01f0bca780 [ 2940.408495] FS: 0000000000000000(0000) GS:ffff8c01f7cc0000(0000) knlGS:0000000000000000 [ 2940.409671] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 2940.410845] CR2: 0000000000000044 CR3: 00000001306fb000 CR4: 00000000000006e0 [ 2940.412049] Call Trace: [ 2940.413276] skb_dequeue+0x1d/0x70 [ 2940.414511] bcsp_dequeue+0x27/0x180 [hci_uart] [ 2940.415760] hci_uart_write_work+0xc4/0x100 [hci_uart] [ 2940.417012] process_one_work+0x151/0x410 [ 2940.418248] worker_thread+0x69/0x4b0 [ 2940.419494] kthread+0x114/0x150 [ 2940.420753] ? rescuer_thread+0x340/0x340 [ 2940.422017] ? kthread_park+0x90/0x90 [ 2940.423295] ret_from_fork+0x2c/0x40 [ 2940.424563] Code: 89 e5 e8 22 55 98 ff 5d c3 66 66 66 66 90 55 48 89 e5 53 9c 58 66 66 90 66 90 48 89 c3 fa 66 66 90 66 66 90 31 c0 ba 01 00 00 00 <f0> 0f b1 17 85 c0 75 06 48 89 d8 5b 5d c3 89 c6 e8 c9 41 98 ff [ 2940.427448] RIP: _raw_spin_lock_irqsave+0x22/0x40 RSP: ffffb2a704d37da8 [ 2940.428956] CR2: 0000000000000044 [ 2940.435363] ---[ end trace 26e358778a5b55c5 ]--- Analysis ======== The kernel crashes because the work queue hu->write_work runs hci_uart_write_work() which attempts to dequeue a Data Layer protocol frame using hu->proto->dequeue(). Unfortunately, hci_uart_tty_close() has already called hu->proto->close() which removes the resources needed by hu->proto->dequeue() and a kernel crash occurs. Assuming device is hci0 (my actual test used hci1). hciattach or btattach can be used and are examples. Example normal case scenario: ----------------------------- 1. hciconfig hci0 up ==> hci_dev_do_open() and sets HCI_UP 2. hciconfig hci0 down ==> hci_dev_do_close() and clears HCI_UP 3. killall hciattach ==> hci_dev_do_close() exits early as HCI_UP is clear Notice that hci_dev_do_close() runs twice. There is probably many seconds between these events so the HCI layer is likely to be idle before hci_uart_tty_close() runs. Therefore, in an environment where the communications with the Bluetooth Radio Module are good, the kernel crash is very unlikely to occur. Example failure case scenario: ------------------------------ 1. hciconfig hci0 up ==> hci_dev_do_open() and sets HCI_UP 2. killall hciattach ==> hci_dev_do_close() and clears HCI_UP In the failure case, hci_dev_do_close() attempts to perform clean-up because HCI_UP is in the set state. hci_dev_do_close() is running in the callstack: hci_uart_tty_close() hci_unregister_dev() hci_dev_do_close() hci_uart_tty_close() is acting against hci_dev_do_close() by systematically inhibiting various aspects of the data plane between the Data Link protocol layer and the UART driver. This seems to be a design flaw; either allow successful transmissions OR fully inhibit transmissions. Unfortunately, the design is attempting both at the same time. When hci_unregister_dev() returns to hci_uart_tty_close(), 1 or more HCI commands might have been queued inside the Data Link protocol layer by hu->proto->enqueue(). The Data Link protocol layer may attempt to periodically retransmit these HCI commands. In any case, attempts at sending any HCI commands will fail during the execution of hci_uart_tty_close() because the data plane between the Data Link protocol Layer and the UART driver has been cut in various places including inside the TTY layer. The weakness in hci_uart_tty_close() is that hu->proto->close() is not prevented from running before or during the execution of the other "proto" function pointers such as hu->proto->dequeue(). Therefore a race condition exists. Solution implemented by this patchset ===================================== When the flag HCI_UART_PROTO_READY is in the clear state, this means the "proto" layer is no longer ready. Therefore use HCI_UART_PROTO_READY to prevent any "proto" function pointer except hu->proto->close() from running. Already protected: p->open() in hci_uart_set_proto() hu->proto->flush() in hci_uart_flush() hu->proto->close() in hci_uart_tty_close() p->close() in hci_uart_set_proto() hu->proto->close() in hci_uart_init_work() The following "proto" functions pointers are now protected by the patchset: hu->proto->enqueue() in hci_uart_send_frame() hu->proto->dequeue() in hci_uart_dequeue() by the implementations in the patches: Bluetooth: hci_ldisc: Add protocol check to hci_uart_send_frame() Bluetooth: hci_ldisc: Add protocol check to hci_uart_dequeue() This protection helps to avoid the kernel crash by ensuring that a "proto" function pointer except hu->proto->close() does not run after HCI_UART_PROTO_READY has been cleared in hci_uart_tty_close(). However, a complete solution (not implemented in this patchset) requires locking to prevent hu->proto->close() from running whilst another "proto" function pointer is already running. The flag HCI_UART_PROTO_READY is insufficient because another "proto" function pointer may already be running at the point the flag is cleared. In addition the patch: Bluetooth: hci_ldisc: Add protocol check to hci_uart_tx_wakeup() prevents the scheduling of new or retransmitted HCI commands from being queued on the work queue hu->write_work so that hci_uart_write_work() is not able to run when HCI_UART_PROTO_READY is in the cleared state. This inhibits transmission attempts so reduces the probability of hci_uart_write_work() running after hu->proto->close() has run. Test results with patchset applied ================================== snippet of dmesg log [ 1122.904072] hci_uart_tty_close: tty ffff91b59c41c000 [ 1122.904075] hci_uart_close: hdev ffff91b59c456000 [ 1122.904078] hci_uart_flush: hdev ffff91b59c456000 tty ffff91b59c41c000 [ 1122.904080] bcsp_flush: hu ffff91b5a29340c0 [ 1122.904085] hci_unregister_dev: ffff91b59c456000 name hci1 bus 3 [ 1122.984911] bcsp_timed_event: hu ffff91b5a29340c0 retransmitting 2 pkts [ 1124.520958] Bluetooth: hci1 command 0x1001 tx timeout [ 1124.521009] hci_cmd_work: hci1 cmd_cnt 1 cmd queued 1 [ 1124.521013] hci_send_frame: hci1 type 1 len 3 [ 1124.521015] hci_uart_send_frame: hci1: type 1 len 3 [ 1124.521016] Bluetooth: hci1 sending frame failed (-49) [ 1126.569048] Bluetooth: hci1 command 0x1009 tx timeout [ 1126.569065] hci_cmd_work: hci1 cmd_cnt 1 cmd queued 0 [ 1130.665151] hci_uart_close: hdev ffff91b59c456000 [ 1130.665154] hci_uart_flush: hdev ffff91b59c456000 tty ffff91b59c41c000 [ 1130.665173] hci_dev_do_close: hci1 ffff91b59c456000 [ 1130.665357] hci_conn_params_clear_all: All LE connection parameters were removed [ 1130.665361] bcsp_close: hu ffff91b5a29340c0 Notice the following error message is now output: Bluetooth: hci1 sending frame failed (-49) This is because the patch Bluetooth: hci_ldisc: Add protocol check to hci_uart_send_frame() is preventing hci_send_frame() from calling hu->proto->enqueue() after hci_uart_tty_close() has cleared the flag HCI_UART_PROTO_READY. Therefore, no new HCI commands can be queued within the Data Link protocol layer because the Data Link protocol layer is pending to be closed. Conclusions =========== This patchset demonstrates the following design issues: 1. Attempts are made at trying to send HCI commands during hci_uart_tty_close() but this is in conflict with the hci_uart_tty_close() closure procedures. 2. Data Link protocol layer retransmission attempts can occur during hci_uart_tty_close() to resend HCI commands but this is in conflict with the hci_uart_tty_close() closure procedures. 3. Sending of HCI commands fail anyway during hci_uart_tty_close() because the data plane between the Data Link protocol layer and the UART driver has been cut in various places including inside the TTY layer. Therefore the attempts at sending HCI commands during hci_uart_tty_close() are futile. This means that, currently the design is attempting to send HCI commands AND trying to inhibit transmissions at the same time. Therefore, there is a conflict in the procedures. The design of hci_uart_tty_close() needs to be changed to either a) allow sucessful transmission of HCI commands and implement a clean controlled closure of the Data Link protocol. OR b) abruptly inhibit further communications of the Data Link protocol. Side-effects ------------ The patchset should be safe although a side-effect could be some occassional error messages: Bluetooth: hci1 sending frame failed (-49) Note hci_send_frame() does not propagate the -EUNATCH (-49) error code so takes no specific action. Therefore, hci_core.c handling is not modified by the patchset. Dean Jenkins (3): Bluetooth: hci_ldisc: Add protocol check to hci_uart_send_frame() Bluetooth: hci_ldisc: Add protocol check to hci_uart_dequeue() Bluetooth: hci_ldisc: Add protocol check to hci_uart_tx_wakeup() drivers/bluetooth/hci_ldisc.c | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) -- 2.7.4 -- To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
