偶然的一次测试中发现了这一问题，在不断的连断HFP协议的时候，一次端RFCOMM连接中远端发来DISC命令，随后几乎同时发来了l2cap连接，本地Host端立即接受了断l2cap连接，还没来得及回复远端的DISC命令已经断完了l2cap连接，或者说断l2cap连接与RFCOMM回复DISC命令时同时进行，但是RFCOMM层回复DISC命令会稍微慢于l2cap断连接。在已经断了l2cap的情况下，l2cap资源已经释放，锁资源也释放了。本地在回复RFCOMM的DISC命令发送UA命令时，发到l2cap层时加锁发送命令，锁资源已经不存在，所以加锁的时候崩溃了，从内核的log中也可以看到。
内核的部分syslog如下：
[ 5956.093941] Bluetooth: bad checksum in packet
[ 5957.735360] Bluetooth: Unknown control type 0x10
[ 5957.741376] Bluetooth: Unknown control type 0x30
[ 5957.747333] Bluetooth: Unknown control type 0x34
[ 5957.754427] Bluetooth: bad checksum in packet
[ 5958.918615] Bluetooth: bad checksum in packet
[ 5959.427632] BUG: unable to handle kernel NULL pointer dereference at 00000010
[ 5959.427636] IP: [<f840f716>] l2cap_chan_send+0x76/0x930 [bluetooth]
[ 5959.427647] *pde = 00000000
[ 5959.427650] Oops: 0000 [#1] SMP
[ 5959.427652] Modules linked in: bnep nfnetlink_queue nfnetlink_log nfnetlink hci_uart ftdi_sio usbserial i915 fbcon tileblit font bitb
[ 5959.427684] Pid: 1296, comm: krfcommd Tainted: G O 3.8.13.13 #1 Dell Inc. Latitude E5470/0P88J9
[ 5959.427687] EIP: 0060:[<f840f716>] EFLAGS: 00010297 CPU: 3
[ 5959.427692] EIP is at l2cap_chan_send+0x76/0x930 [bluetooth]
[ 5959.427694] EAX: 00000000 EBX: c5a22c00 ECX: 00000004 EDX: c5a22c00
[ 5959.427695] ESI: 00000000 EDI: c5a22c00 EBP: c9b85da0 ESP: c9b85d48
[ 5959.427696] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[ 5959.427697] CR0: 80050033 CR2: 00000010 CR3: 06a0c000 CR4: 003407d0
[ 5959.427699] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 5959.427700] DR6: ffff0ff0 DR7: 00000400
[ 5959.427701] Process krfcommd (pid: 1296, ti=c9b84000 task=c99c4c80 task.ti=c9b84000)
[ 5959.427702] Stack:
[ 5959.427703] 00000001 00000000 00000004 0000024d 00000000 c9b85ebc ffffffa6 c9b85d90
[ 5959.427707] c0643972 80486713 0000056b c5a22c00 000003ff f641c500 c9b85e08 c5a22e4c
[ 5959.427711] c9b85ebc ea94d400 c9b85da0 c5a22c00 c9b85ebc ea94d400 c9b85dc0 f8413451
[ 5959.427715] Call Trace:
[ 5959.427719] [<c0643972>] ? mutex_lock_slowpath+0x32/0x120
[ 5959.427725] [<f8413451>] l2cap_sock_sendmsg+0x61/0x90 [bluetooth]
[ 5959.427728] [<c0550b01>] sock_sendmsg+0xd1/0xf0
[ 5959.427731] [<c06443e9>] ? schedule+0x3a9/0x7e0
[ 5959.427734] [<fae00ab0>] ? rfcomm_dlc_alloc+0x30/0xe0 [rfcomm]
[ 5959.427736] [<c0550b54>] kernel_sendmsg+0x34/0x50
[ 5959.427739] [<fae0032b>] rfcomm_send_frame.isra.5+0x3b/0x40 [rfcomm]
[ 5959.427742] [<fae00582>] rfcomm_send_ua+0x62/0x70 [rfcomm]
[ 5959.427745] [<fae01ed0>] rfcomm_run+0x890/0x11e0 [rfcomm]
[ 5959.427748] [<fae01640>] ? rfcomm_check_accept+0xa0/0xa0 [rfcomm]
[ 5959.427751] [<c0158134>] kthread+0x94/0xa0
[ 5959.427753] [<c064c9bb>] ret_from_kernel_thread+0x1b/0x30
[ 5959.427756] [<c01580a0>] ? flush_kthread_worker+0x90/0x90
[ 5959.427757] Code: 39 45 b0 0f 86 dc 02 00 00 8b 45 c0 83 c4 4c 5b 5e 5f 5d c3 90 8b 55 d4 c7 45 c0 a6 ff ff ff 0f b7 42 1e 39 45 b0 7
[ 5959.427785] EIP: [<f840f716>] l2cap_chan_send+0x76/0x930 [bluetooth] SS:ESP 0068:c9b85d48
[ 5959.427791] CR2: 0000000000000010
[ 5959.427793] ---[ end trace 9070b47c84680a8e ]---
[ 6357.710107] Bluetooth: hci0 link tx timeout
[ 6357.710126] Bluetooth: hci0 killing stalled connection 00:1e:ab:4c:50:e7
[ 7266.495913] usb 1-1: USB disconnect, device number 4
[ 7266.496044] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
[ 7266.496073] ftdi_sio 1-1:1.0: device disconnected
[ 7266.497038] ftdi_sio ttyUSB1: FTDI USB Serial Device converter now disconnected from ttyUSB1
[ 7266.497051] ftdi_sio 1-1:1.1: device disconnected
anager[1209]: <info> sleep requested (sleeping: no enabled: yes)
anager[1209]: <info> sleeping or disabling...
anager[1209]: <info> (eth0): now unmanaged
anager[1209]: <info> (eth0): device state change: unavailable -> unmanaged (reason 'sleeping') [20 10 37]
anager[1209]: <info> (eth0): cleaning up...
anager[1209]: <info> (eth0): taking down device.
[ 7266.988991] e1000e: eth0 NIC Link is Down
[ 7267.595439] ACPI Error: [_SB.PCI0.LPCB.H_EC.CHRG] Namespace lookup failure, AE_NOT_FOUND (20121018/psargs-359)
[ 7267.595475] ACPI Error: Method parse/execution failed [\PNOT] (Node f5c4a5b8), AE_NOT_FOUND (20121018/psparse-537)
[ 7267.595509] ACPI Error: Method parse/execution failed [_SB.AC._PSR] (Node f5c51990), AE_NOT_FOUND (20121018/psparse-537)
[ 7267.595592] ACPI Exception: AE_NOT_FOUND, Error reading AC Adapter state (20121018/ac-122)
[ 7270.166817] PM: Syncing filesystems ... done.
[ 7270.173616] PM: Preparing system for mem sleep
[ 7270.173705] Freezing user space processes ...
[ 7290.156755] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze, wq_busy=0):
[ 7290.156825] bt_daemon_d D 00000096 0 3497 1 0x00000006
[ 7290.156836] ebc6fcf0 00000046 00000003 00000096 00000000 f5cf9980 c0964500 c0964500
[ 7290.156851] 591f45b9 000005cc f6443500 f1335940 f101d940 c0150b2e ebc6fcb4 c0151375
[ 7290.156865] 00000000 f6444300 ebc6fce4 c0151469 00000000 f5c01300 00000001 00c6fcf0
[ 7290.156879] Call Trace:
[ 7290.156894] [<c0150b2e>] ? wake_up_worker+0x1e/0x30
[ 7290.156902] [<c0151375>] ? insert_work+0x75/0x80
[ 7290.156909] [<c0151469>] ? __queue_work+0xe9/0x320
[ 7290.156927] [<c0644ac3>] schedule+0x23/0x60
[ 7290.156935] [<c0644d0d>] schedule_preempt_disabled+0xd/0x10
[ 7290.156942] [<c0643a06>] __mutex_lock_slowpath+0xc6/0x120
[ 7290.156952] [<c06436b4>] mutex_lock+0x24/0x40
[ 7290.156963] [<fae0124f>] rfcomm_dlc_close+0x1f/0x40 [rfcomm]
[ 7290.156973] [<fae02f44>] __rfcomm_sock_close+0x84/0x90 [rfcomm]
[ 7290.156983] [<fae02f08>] __rfcomm_sock_close+0x48/0x90 [rfcomm]
[ 7290.156993] [<fae031b8>] rfcomm_sock_shutdown+0x58/0x80 [rfcomm]
[ 7290.157002] [<fae03207>] rfcomm_sock_release+0x27/0x80 [rfcomm]
[ 7290.157013] [<c0551480>] sock_release+0x20/0x80
[ 7290.157021] [<c0551897>] sock_close+0x17/0x30
[ 7290.157030] [<c022c807>] __fput+0x97/0x200
[ 7290.157038] [<c022c97d>] ____fput+0xd/0x10
[ 7290.157046] [<c0155451>] task_work_run+0xb1/0xd0
[ 7290.157056] [<c02555e7>] ? exit_fs+0x77/0x90
[ 7290.157064] [<c013dfb0>] do_exit+0x280/0x940
[ 7290.157073] [<c0149447>] ? recalc_sigpending+0x17/0x50
[ 7290.157082] [<c01496e1>] ? dequeue_signal+0x31/0x190
[ 7290.157090] [<c013e7e8>] do_group_exit+0x38/0xa0
[ 7290.157100] [<c014b861>] get_signal_to_deliver+0x1d1/0x5b0
[ 7290.157108] [<c01021ba>] do_signal+0x2a/0x990
[ 7290.157117] [<c0190379>] ? do_futex+0x2d9/0x970
[ 7290.157126] [<c0263e78>] ? fsnotify+0x198/0x250
[ 7290.157134] [<c0190afd>] ? sys_futex+0xed/0x130
[ 7290.157143] [<c0102ca5>] do_notify_resume+0x55/0x80
[ 7290.157152] [<c0645cb5>] work_notifysig+0x30/0x3b
[ 7290.157160]
lient 1379[0:0] has disconnected
[ 7290.157164] Restarting tasks ... done.
lient connected from 1379[0:0]
client rule loaded
5978]: Anacron 2.3 started on 2017-06-08
5978]: Normal exit (0 jobs run)
anager[1209]: <info> wake requested (sleeping: yes enabled: yes)
anager[1209]: <info> waking up and re-enabling...
anager[1209]: <info> WWAN now enabled by management service
anager[1209]: <info> (eth0): now managed
anager[1209]: <info> (eth0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
anager[1209]: <info> (eth0): bringing up device.
[ 7290.791621] e1000e 0000:00:1f.6: setting latency timer to 64
[ 7291.151227] e1000e 0000:00:1f.6: irq 140 for MSI/MSI-X
anager[1209]: <info> (eth0): preparing device.
anager[1209]: <info> (eth0): deactivating device (reason 'managed') [2]
[ 7291.254912] e1000e 0000:00:1f.6: irq 140 for MSI/MSI-X
[ 7291.255078] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 7444.582525] usb 1-3: new high-speed USB device number 5 using xhci_hcd
[ 7444.599916] ftdi_sio 1-3:1.0: FTDI USB Serial Device converter detected
[ 7444.599970] usb 1-3: Detected FT2232H
[ 7444.599975] usb 1-3: Number of endpoints 2
[ 7444.599981] usb 1-3: Endpoint 1 MaxPacketSize 512
[ 7444.599985] usb 1-3: Endpoint 2 MaxPacketSize 512
[ 7444.599989] usb 1-3: Setting MaxPacketSize 512
[ 7444.600262] usb 1-3: FTDI USB Serial Device converter now attached to ttyUSB0
[ 7444.600439] ftdi_sio 1-3:1.1: FTDI USB Serial Device converter detected
[ 7444.600479] usb 1-3: Detected FT2232H
[ 7444.600484] usb 1-3: Number of endpoints 2
[ 7444.600489] usb 1-3: Endpoint 1 MaxPacketSize 512
[ 7444.600493] usb 1-3: Endpoint 2 MaxPacketSize 512
[ 7444.600498] usb 1-3: Setting MaxPacketSize 512
[ 7444.600645] usb 1-3: FTDI USB Serial Device converter now attached to ttyUSB1
e: checking bus 1, device 5: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-3"
e: bus: 1, device: 5 was not an MTP device
[ 7471.474545] usb 1-3: USB disconnect, device number 5
[ 7471.475088] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
[ 7471.475137] ftdi_sio 1-3:1.0: device disconnected
[ 7471.475515] ftdi_sio ttyUSB1: FTDI USB Serial Device converter now disconnected from ttyUSB1
[ 7471.475562] ftdi_sio 1-3:1.1: device disconnected
[ 7471.803876] usb 1-3: new high-speed USB device number 6 using xhci_hcd
[ 7471.821584] ftdi_sio 1-3:1.0: FTDI USB Serial Device converter detected
[ 7471.821686] usb 1-3: Detected FT2232H
网友评论