search

raspberrypi / firmware

This repository contains pre-compiled binaries of the current Raspberry Pi kernel and modules, userspace libraries, and bootloader/GPU firmware.
5.19k stars 1.68k forks source link

Bluetooth: hci0: Frame reassembly failed (-84) #1150

Open risa2000 opened 5 years ago

risa2000 commented 5 years ago

After the last system upgrade of Raspbian to:

pi@hass:~ $ uname -a
Linux hass 4.19.42-v7+ #1219 SMP Tue May 14 21:20:58 BST 2019 armv7l GNU/Linux

I am observing a problem with bluetooth, which, after some time, stops working. The kernel log shows repeating message

Bluetooth: hci0: Frame reassembly failed (-84)

or sometimes also a stack dump (I do not have one right now).

The RPi is 3B the dmesg log is here: dmesg.log

The HCI configuration is:

pi@hass:~ $ hciconfig -a
hci0:   Type: Primary  Bus: UART
        BD Address: B8:27:EB:A1:A8:DE  ACL MTU: 1021:8  SCO MTU: 64:1
        UP RUNNING
        RX bytes:1733551 acl:20475 sco:1 events:67235 errors:0
        TX bytes:387061 acl:5214 sco:0 commands:27972 errors:0
        Features: 0xbf 0xfe 0xcf 0xfe 0xdb 0xff 0x7b 0x87
        Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
        Link policy: RSWITCH SNIFF
        Link mode: SLAVE ACCEPT
        Name: 'hass'
        Class: 0x000000
        Service Classes: Unspecified
        Device Class: Miscellaneous,
        HCI Version: 4.1 (0x7)  Revision: 0x168
        LMP Version: 4.1 (0x7)  Subversion: 0x2209
        Manufacturer: Broadcom Corporation (15)

Now my BT usage is a bit specific. The main role for this RPi is running homeassistant, which means (among others) having: USB flash stick (with f2fs for logging), Z-Wave USB stick for home automation, Zigbee USB stick for home automation, and also using built-in BT for tracking BT hygrothermo devices.

Apart from that, I also (ab)use the built-in BT for controlling Valve's lighthouses. Both the hygrothermo devices and the lighthouses use BTLE protocol. HT devices are read-out every 2 minutes, the lighthouses (when running) are talked to every 20 seconds.

When I do not run the lighthouses there is no communication with them and the error seems far less likely to happen. When I run a VR session, and run the lighthouse control, after some time, the BT becomes unresponsive, the errors are logged in the kernel log and the only resolution is a reboot.

Before the last system (and I assume also the firmware) upgrade, the system worked, in the exactly same configuration, fine, for several months.

pelwell commented 5 years ago

The 3B doesn't have the flow control signals hooked up to the BT modem - we were short of pins - so it is possible for characters to get lost under load (especially interrupt load). What sort of data rate is typical for your application? If the rate is low, you may find that reducing the baud rate by editing /usr/bin/btuart gets a more stable connection.

risa2000 commented 5 years ago

@pelwell I believe I can go with lower rate, my use is light and also nothing happens if one packet is lost.

What however bothers me (and I am not sure it is actually evident from the message as I am not familiar with BT) is not the intermittent corruption of the data, but the fact that BT becomes completely unresponsive.

This is what started to happen (I believe) with the latest update. I had some missed comms before, but then, the comm recovered the next time the connection was retried and it never led to the state where I need to reboot the RPi to get BT working again.

J-Luc16 commented 5 years ago

built-in BT for tracking BT hygrothermo devices.

Same sort of application (temp+hygro for a plant dryer), same issue since the last kernel update (may ?) on my PI3,

I have put an USB dongle and it works, but I am not happy with this solution, the integrated BTLE of PI3 was stable for months before, now it crashes within one day or 2.

GorkaMM commented 5 years ago

It stopped working for me too on my Raspberry Pi 3 after the update.

codyc1515 commented 5 years ago

I am having this issue as well and it's just continuous of the following.

[98613.228402] Bluetooth: hci0: SCO packet for unknown connection handle 23967 [98659.629015] Bluetooth: hci0: Frame reassembly failed (-84) [98659.629051] Bluetooth: hci0: hardware error 0xc5

My version is Linux hoobs 4.19.42-v7+ #1219 SMP Tue May 14 21:20:58 BST 2019 armv7l GNU/Linux.

codyc1515 commented 5 years ago

This worked for me:

sudo rpi-update c50c65e52bad69e8fa7d6576d9e2399eade7faf6

J-Luc16 commented 5 years ago

Cool, is this workaround a regression to the previous version of the firmware ?

pelwell commented 5 years ago

There may be a related issue - https://github.com/raspberrypi/firmware/issues/1017. I've found a driver/hardware bug with a simple workaround which I'm prepared to merge if the real fix doesn't appear soon.

pelwell commented 5 years ago

A real fix has been found and pushed to rpi-4.19.y - see https://github.com/raspberrypi/linux/commit/9bf5cd2dc5bf4680ec14b372fae5b457c6ccb497

Hopefully a firmware with the fix will be released in the next few days.

milou161185 commented 5 years ago

hi, i have the same problem and the fix "sudo rpi-update c50c65e52bad69e8fa7d6576d9e2399eade7faf6" don't worked for me. Is the new firmware corrected available? If no, is there any other workaround?

bieniu commented 5 years ago

@milou161185 I had to downgrade kernel to version 4.14.98 to fix this issue.

pelwell commented 5 years ago

I don't know where you got that commit hash, but it's wrong. Try sudo rpi-update 43fa687c, which at least includes the patch.

milou161185 commented 5 years ago

thanks @pelwell but i try "sudo rpi-update 43fa687c" and i have the same error in the log

pelwell commented 5 years ago

  1. Which platform are you on?

  2. Which distribution are you running?

  3. What are you doing when the error appears?

  4. How long does the error take to occur?

milou161185 commented 5 years ago

1 : Linux raspberrypi 4.19.58-v7+ #1245 SMP Fri Jul 12 17:25:51 BST 2019 armv7l GNU/Linux 2 : Raspbian GNU/Linux 9 \n \l 3 : nothing, just after booting 4 : these errors appeared after an update

pelwell commented 5 years ago

  1. Which model of Raspberry Pi?

  2. And they happen after every reboot?

Please paste the output of dmesg after booting.

milou161185 commented 5 years ago

5 : Pi model 3B 6 : yes after every reboot

dmesg :

[ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Linux version 4.19.58-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1245 SMP Fri Jul 12 17:25:51 BST 2019 [ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d [ 0.000000] CPU: div instructions available: patching division code [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache [ 0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2 [ 0.000000] Memory policy: Data cache writealloc [ 0.000000] cma: Reserved 8 MiB at 0x36800000 [ 0.000000] On node 0 totalpages: 225280 [ 0.000000] Normal zone: 1980 pages used for memmap [ 0.000000] Normal zone: 0 pages reserved [ 0.000000] Normal zone: 225280 pages, LIFO batch:63 [ 0.000000] random: get_random_bytes called from start_kernel+0xac/0x4b4 with crng_init=0 [ 0.000000] percpu: Embedded 17 pages/cpu s39488 r8192 d21952 u69632 [ 0.000000] pcpu-alloc: s39488 r8192 d21952 u69632 alloc=17*4096 [ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 223300 [ 0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 bcm2708_fb.fbwidth=800 bcm2708_fb.fbheight=480 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3dc00000 vc_mem.mem_size=0x3f000000 dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=/dev/mmcblk0p7 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait [ 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: 870068K/901120K available (8192K kernel code, 629K rwdata, 2176K rodata, 1024K init, 821K bss, 22860K reserved, 8192K cma-reserved) [ 0.000000] Virtual kernel memory layout: vector : 0xffff0000 - 0xffff1000 ( 4 kB) fixmap : 0xffc00000 - 0xfff00000 (3072 kB) vmalloc : 0xb7800000 - 0xff800000 (1152 MB) lowmem : 0x80000000 - 0xb7000000 ( 880 MB) modules : 0x7f000000 - 0x80000000 ( 16 MB) .text : 0x(ptrval) - 0x(ptrval) (9184 kB) .init : 0x(ptrval) - 0x(ptrval) (1024 kB) .data : 0x(ptrval) - 0x(ptrval) ( 630 kB) .bss : 0x(ptrval) - 0x(ptrval) ( 822 kB) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] ftrace: allocating 26351 entries in 78 pages [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16 [ 0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys). [ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns [ 0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns [ 0.000023] Switching to timer-based delay loop, resolution 52ns [ 0.000286] Console: colour dummy device 80x30 [ 0.000906] console [tty1] enabled [ 0.000962] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000) [ 0.001008] pid_max: default: 32768 minimum: 301 [ 0.001365] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.001401] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.002343] CPU: Testing write buffer coherency: ok [ 0.002826] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 [ 0.003500] Setting up static identity map for 0x100000 - 0x10003c [ 0.003667] rcu: Hierarchical SRCU implementation. [ 0.004484] smp: Bringing up secondary CPUs ... [ 0.005345] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 [ 0.006269] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002 [ 0.007131] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003 [ 0.007251] smp: Brought up 1 node, 4 CPUs [ 0.007334] SMP: Total of 4 processors activated (153.60 BogoMIPS). [ 0.007358] CPU: All CPU(s) started in HYP mode. [ 0.007378] CPU: Virtualization extensions available. [ 0.008361] devtmpfs: initialized [ 0.021351] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4 [ 0.021626] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.021674] futex hash table entries: 1024 (order: 4, 65536 bytes) [ 0.022283] pinctrl core: initialized pinctrl subsystem [ 0.023158] NET: Registered protocol family 16 [ 0.026120] DMA: preallocated 1024 KiB pool for atomic coherent allocations [ 0.031782] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers. [ 0.031818] hw-breakpoint: maximum watchpoint size is 8 bytes. [ 0.032039] Serial: AMBA PL011 UART driver [ 0.034583] bcm2835-mbox 3f00b880.mailbox: mailbox enabled [ 0.069412] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1 [ 0.071345] SCSI subsystem initialized [ 0.071582] usbcore: registered new interface driver usbfs [ 0.071664] usbcore: registered new interface driver hub [ 0.071776] usbcore: registered new device driver usb [ 0.090289] raspberrypi-firmware soc:firmware: Attached to firmware from 2019-07-12 17:39, variant start_x [ 0.100122] raspberrypi-firmware soc:firmware: Firmware hash is 578479b20dbfea64cd822278fb70eee7a56c97e4 [ 0.111802] clocksource: Switched to clocksource arch_sys_counter [ 0.201721] VFS: Disk quotas dquot_6.6.0 [ 0.201853] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) [ 0.202064] FS-Cache: Loaded [ 0.202290] CacheFiles: Loaded [ 0.212301] NET: Registered protocol family 2 [ 0.213088] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes) [ 0.213153] TCP established hash table entries: 8192 (order: 3, 32768 bytes) [ 0.213285] TCP bind hash table entries: 8192 (order: 4, 65536 bytes) [ 0.213490] TCP: Hash tables configured (established 8192 bind 8192) [ 0.213643] UDP hash table entries: 512 (order: 2, 16384 bytes) [ 0.213709] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes) [ 0.214036] NET: Registered protocol family 1 [ 0.214636] RPC: Registered named UNIX socket transport module. [ 0.214663] RPC: Registered udp transport module. [ 0.214685] RPC: Registered tcp transport module. [ 0.214706] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.216361] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available [ 0.219396] Initialise system trusted keyrings [ 0.219605] workingset: timestamp_bits=14 max_order=18 bucket_order=4 [ 0.229338] FS-Cache: Netfs 'nfs' registered for caching [ 0.229917] NFS: Registering the id_resolver key type [ 0.229961] Key type id_resolver registered [ 0.229984] Key type id_legacy registered [ 0.230015] nfs4filelayout_init: NFSv4 File Layout Driver Registering... [ 0.232374] Key type asymmetric registered [ 0.232406] Asymmetric key parser 'x509' registered [ 0.232474] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250) [ 0.232660] io scheduler noop registered [ 0.232685] io scheduler deadline registered (default) [ 0.232893] io scheduler cfq registered [ 0.232917] io scheduler mq-deadline registered (default) [ 0.232942] io scheduler kyber registered [ 0.236164] bcm2708_fb soc:fb: FB found 1 display(s) [ 0.248117] Console: switching to colour frame buffer device 100x30 [ 0.256924] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 800x480 [ 0.261910] bcm2835-rng 3f104000.rng: hwrng registered [ 0.265029] vc-mem: phys_addr:0x00000000 mem_base=0x3dc00000 mem_size:0x3f000000(1008 MiB) [ 0.268583] vc-sm: Videocore shared memory driver [ 0.272015] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000 [ 0.285893] brd: module loaded [ 0.298948] loop: module loaded [ 0.302593] Loading iSCSI transport class v2.0-870. [ 0.306237] libphy: Fixed MDIO Bus: probed [ 0.309241] usbcore: registered new interface driver lan78xx [ 0.312305] usbcore: registered new interface driver smsc95xx [ 0.315210] dwc_otg: version 3.00a 10-AUG-2012 (platform bus) [ 0.346028] dwc_otg 3f980000.usb: base=(ptrval) [ 0.549149] Core Release: 2.80a [ 0.552002] Setting default values for core params [ 0.554881] Finished setting default values for core params [ 0.758005] Using Buffer DMA mode [ 0.760749] Periodic Transfer Interrupt Enhancement - disabled [ 0.763597] Multiprocessor Interrupt Enhancement - disabled [ 0.766471] OTG VER PARAM: 0, OTG VER FLAG: 0 [ 0.769360] Dedicated Tx FIFOs mode [ 0.772682] WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = b6904000 dma = 0xf6904000 len=9024 [ 0.778803] FIQ FSM acceleration enabled for : Non-periodic Split Transactions Periodic Split Transactions High-Speed Isochronous Endpoints Interrupt/Control Split Transaction hack enabled [ 0.793368] dwc_otg: Microframe scheduler enabled [ 0.793425] WARN::hcd_init_fiq:457: FIQ on core 1 [ 0.796170] WARN::hcd_init_fiq:458: FIQ ASM at 80650e04 length 36 [ 0.798850] WARN::hcd_init_fiq:497: MPHI regs_base at b7810000 [ 0.801548] dwc_otg 3f980000.usb: DWC OTG Controller [ 0.804299] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1 [ 0.807087] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000 [ 0.809838] Init: Port Power? op_state=1 [ 0.812599] Init: Power Port (0) [ 0.815521] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19 [ 0.818398] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 0.821276] usb usb1: Product: DWC OTG Controller [ 0.824148] usb usb1: Manufacturer: Linux 4.19.58-v7+ dwc_otg_hcd [ 0.827028] usb usb1: SerialNumber: 3f980000.usb [ 0.830466] hub 1-0:1.0: USB hub found [ 0.833307] hub 1-0:1.0: 1 port detected [ 0.836598] dwc_otg: FIQ enabled [ 0.836604] dwc_otg: NAK holdoff enabled [ 0.836610] dwc_otg: FIQ split-transaction FSM enabled [ 0.836621] Module dwc_common_port init [ 0.836896] usbcore: registered new interface driver usb-storage [ 0.839845] mousedev: PS/2 mouse device common for all mice [ 0.843544] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer [ 0.846540] bcm2835-cpufreq: min=600000 max=1200000 [ 0.849640] sdhci: Secure Digital Host Controller Interface driver [ 0.852344] sdhci: Copyright(c) Pierre Ossman [ 0.855391] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe [ 0.858582] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe [ 0.861580] sdhci-pltfm: SDHCI platform and OF driver helper [ 0.866011] ledtrig-cpu: registered to indicate activity on CPUs [ 0.869095] hidraw: raw HID events driver (C) Jiri Kosina [ 0.872251] usbcore: registered new interface driver usbhid [ 0.875215] usbhid: USB HID core driver [ 0.878891] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0

[ 0.893215] [vc_sm_connected_init]: end - returning 0 [ 0.897271] Initializing XFRM netlink socket [ 0.900250] NET: Registered protocol family 17 [ 0.903271] Key type dns_resolver registered [ 0.906558] Registering SWP/SWPB emulation handler [ 0.910017] registered taskstats version 1 [ 0.912830] Loading compiled-in X.509 certificates [ 0.922774] uart-pl011 3f201000.serial: cts_event_workaround enabled [ 0.925749] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2 [ 0.930728] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0 [ 0.933859] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated [ 0.963072] sdhost: log_buf @ (ptrval) (f6907000) [ 1.000930] mmc1: queuing unknown CIS tuple 0x80 (2 bytes) [ 1.005537] mmc1: queuing unknown CIS tuple 0x80 (3 bytes) [ 1.009997] mmc1: queuing unknown CIS tuple 0x80 (3 bytes) [ 1.015636] mmc1: queuing unknown CIS tuple 0x80 (7 bytes) [ 1.018341] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1) [ 1.022291] of_cfs_init [ 1.024962] of_cfs_init: OK [ 1.028062] Waiting for root device /dev/mmcblk0p7... [ 1.052013] Indeed it is in host mode hprt0 = 00021501 [ 1.126003] random: fast init done [ 1.172861] mmc0: host does not support reading read-only switch, assuming write-enable [ 1.179146] mmc0: new high speed SDHC card at address aaaa [ 1.182932] mmcblk0: mmc0:aaaa SC16G 14.8 GiB [ 1.193802] mmcblk0: p1 p2 < p5 p6 p7 > [ 1.210440] mmc1: new high speed SDIO card at address 0001 [ 1.216584] EXT4-fs (mmcblk0p7): mounted filesystem with ordered data mode. Opts: (null) [ 1.219398] VFS: Mounted root (ext4 filesystem) readonly on device 179:7. [ 1.230383] devtmpfs: mounted [ 1.238509] Freeing unused kernel memory: 1024K [ 1.261846] usb 1-1: new high-speed USB device number 2 using dwc_otg [ 1.264793] Indeed it is in host mode hprt0 = 00001101 [ 1.327902] Run /sbin/init as init process [ 1.502159] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00 [ 1.505044] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 [ 1.508528] hub 1-1:1.0: USB hub found [ 1.511379] hub 1-1:1.0: 5 ports detected [ 1.769938] systemd[1]: System time before build time, advancing clock. [ 1.831851] usb 1-1.1: new high-speed USB device number 3 using dwc_otg [ 1.930580] NET: Registered protocol family 10 [ 1.934971] Segment Routing with IPv6 [ 1.962201] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00 [ 1.965534] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 [ 1.971513] smsc95xx v1.0.6 [ 1.973676] random: systemd: uninitialized urandom read (16 bytes read) [ 1.980660] random: systemd: uninitialized urandom read (16 bytes read) [ 1.989789] systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN) [ 2.000343] systemd[1]: Detected architecture arm. [ 2.036138] systemd[1]: Set hostname to . [ 2.086266] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:8f:1e:89 [ 2.093298] random: systemd-cryptse: uninitialized urandom read (16 bytes read) [ 3.029459] systemd[1]: nfs-blkmap.service: Cannot add dependency job, ignoring: Unit nfs-blkmap.service is masked. [ 3.045456] systemd[1]: Created slice User and Session Slice. [ 3.074945] systemd[1]: Listening on udev Control Socket. [ 3.083071] systemd[1]: Listening on udev Kernel Socket. [ 3.091677] systemd[1]: Created slice System Slice. [ 3.100337] systemd[1]: Created slice system-systemd\x2dfsck.slice. [ 3.108833] systemd[1]: Listening on fsck to fsckd communication Socket. [ 3.231623] i2c /dev entries driver [ 3.589514] EXT4-fs (mmcblk0p7): re-mounted. Opts: (null) [ 3.675895] systemd-journald[119]: Received request to flush runtime journal from PID 1 [ 4.112311] rpi-ft5406 rpi_ft5406: Probing device [ 4.113385] input: FT5406 memory based driver as /devices/virtual/input/input0 [ 4.160677] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. [ 4.163409] bcm2835_vc_sm_cma_probe: Videocore shared memory driver

[ 4.172485] [vc_sm_connected_init]: installed successfully [ 4.212879] media: Linux media interface: v0.10 [ 4.279266] videodev: Linux video capture interface: v2.00 [ 4.340172] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. [ 4.340185] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. [ 4.366773] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. [ 4.366802] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. [ 4.383317] bcm2835_audio soc:audio: card created with 8 channels [ 4.385850] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. [ 4.518427] cfg80211: Loading compiled-in X.509 certificates for regulatory database [ 4.627349] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' [ 4.697764] brcmfmac: F1 signature read @0x18000000=0x1541a9a6 [ 4.712437] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1 [ 4.712713] usbcore: registered new interface driver brcmfmac [ 5.004898] bcm2835-codec bcm2835-codec: Device registered as /dev/video10 [ 5.005479] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1 [ 5.005605] brcmfmac: brcmf_c_process_clm_blob: no clm_blob available (err=-2), device may have limited channels available [ 5.006387] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/1 wl0: Oct 23 2017 03:55:53 version 7.45.98.38 (r674442 CY) FWID 01-e58d219f [ 5.006524] bcm2835-codec bcm2835-codec: Loaded V4L2 decode [ 5.016741] bcm2835-codec bcm2835-codec: Device registered as /dev/video11 [ 5.016832] bcm2835-codec bcm2835-codec: Loaded V4L2 encode [ 5.020735] bcm2835-codec bcm2835-codec: Device registered as /dev/video12 [ 5.020748] bcm2835-codec bcm2835-codec: Loaded V4L2 isp [ 5.026775] bcm2835-v4l2: scene mode selected 0, was 0 [ 5.034818] bcm2835-v4l2: V4L2 device registered as video0 - stills mode > 1280x720 [ 5.051676] bcm2835-v4l2: Broadcom 2835 MMAL video capture ver 0.0.2 loaded. [ 5.787592] uart-pl011 3f201000.serial: no DMA platform data [ 6.526206] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 6.526241] brcmfmac: power management disabled [ 7.244336] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup [ 7.244613] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready [ 8.333443] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready [ 8.391995] Under-voltage detected! (0x00050005) [ 10.410110] Bluetooth: Core ver 2.22 [ 10.410164] NET: Registered protocol family 31 [ 10.410168] Bluetooth: HCI device and connection manager initialized [ 10.410181] Bluetooth: HCI socket layer initialized [ 10.410188] Bluetooth: L2CAP socket layer initialized [ 10.410212] Bluetooth: SCO socket layer initialized [ 10.453707] Bluetooth: HCI UART driver ver 2.3 [ 10.453722] Bluetooth: HCI UART protocol H4 registered [ 10.453813] Bluetooth: HCI UART protocol Three-wire (H5) registered [ 10.454033] Bluetooth: HCI UART protocol Broadcom registered [ 11.124429] Bluetooth: BNEP (Ethernet Emulation) ver 1.3 [ 11.124447] Bluetooth: BNEP filters: protocol multicast [ 11.124477] Bluetooth: BNEP socket layer initialized [ 11.257837] Bluetooth: RFCOMM TTY layer initialized [ 11.257876] Bluetooth: RFCOMM socket layer initialized [ 11.257913] Bluetooth: RFCOMM ver 1.11 [ 18.066574] fuse init (API version 7.27) [ 23.541260] EXT4-fs (mmcblk0p5): mounted filesystem with ordered data mode. Opts: (null) [ 27.111915] Voltage normalised (0x00000000) [ 31.272096] Under-voltage detected! (0x00050005) [ 35.432013] Voltage normalised (0x00000000) [ 36.405459] Adding 102396k swap on /var/swap. Priority:-2 extents:1 across:102396k SSFS [ 52.072461] Under-voltage detected! (0x00050005) [ 64.551979] Voltage normalised (0x00000000) [ 90.323059] random: crng init done [ 90.323075] random: 7 urandom warning(s) missed due to ratelimiting [ 104.174398] Bluetooth: hci0: Frame reassembly failed (-84) [ 104.174453] Bluetooth: hci0: Frame reassembly failed (-84) [ 104.178473] Bluetooth: hci0: Frame reassembly failed (-84)

pelwell commented 5 years ago

When your Pi has a marginal power supply (or too much load) as yours seems to, all sorts of errors can happen that wouldn't normally.

milou161185 commented 5 years ago

a screen is connected to the pi, I will try by unplugging it to see if the messages are disappearing

milou161185 commented 5 years ago

the error " Under-voltage detected! " is gone but I still have error messages "Bluetooth: hci0: Frame reassembly failed (-84)" with no screen connected

pelwell commented 5 years ago

Going back to your answer to question 3, an error like the one you are seeing is unlikely on an idle system. Which Bluetooth devices are connected?

milou161185 commented 5 years ago

I use the bluetooth of pi as antenna for jeedom, so there is 2 nut connected

milou161185 commented 5 years ago

by stopping the service making the connection between the pi and jeedom, no error ... I will therefore get closer to the forum jeedom, thank you for your help!

pelwell commented 5 years ago

What is a "nut"? Do you mean the Nut Mini device tracker?

How large and CPU intensive is Jeedom? Unlike the later Bluetooth Pis, Pi 3B doesn't have flow control signals to the Bluetooth modem which means it can lose data under load. One option is to follow the suggestion I gave earlier to reduce the baud rate to the modem - edit /usr/bin/btuart and change the 921600 to 460800 (or 230400, 115200 etc.). Unless you are streaming audio it shouldn't be too restricting.

milou161185 commented 5 years ago

thanks, i try this

milou161185 commented 5 years ago

same problem :(

pelwell commented 5 years ago

I don't think this is an acceptable solution, but to help me understand the problem please try with 115200 if you haven't already.

furiaceka87 commented 5 years ago

What is 115200? Is it a Git Hash for a new firmware?

popcornmix commented 5 years ago

Baud rate of BT uart.

pelwell commented 5 years ago

edit /usr/bin/btuart and change the 921600 to 460800 (or 230400, 115200 etc.).

I don't think this is an acceptable solution, but to help me understand the problem please try with 115200 if you haven't already.

What is 115200?

It's a very low baud rate to put in /usr/bin/btuart.

furiaceka87 commented 5 years ago

At the moment I had:

$HCIATTACH /dev/serial1 bcm43xx 3000000 flow - $BDADDR else $HCIATTACH /dev/serial1 bcm43xx 921600 noflow - $BDADDR fi else $HCIATTACH /dev/serial1 bcm43xx 460800 noflow - $BDADDR

Can I divide everything by a two factor?

uname -a

Linux raspberrypi 4.19.58-v7+ #1245 SMP Fri Jul 12 17:25:51 BST 2019 armv7l GNU/Linux

dmesg for Bluetooth

[ 11.756171] Bluetooth: Core ver 2.22 [ 11.756266] NET: Registered protocol family 31 [ 11.756273] Bluetooth: HCI device and connection manager initialized [ 11.756294] Bluetooth: HCI socket layer initialized [ 11.756308] Bluetooth: L2CAP socket layer initialized [ 11.756347] Bluetooth: SCO socket layer initialized [ 11.775640] Bluetooth: HCI UART driver ver 2.3 [ 11.775654] Bluetooth: HCI UART protocol H4 registered [ 11.775738] Bluetooth: HCI UART protocol Three-wire (H5) registered [ 11.775955] Bluetooth: HCI UART protocol Broadcom registered [ 12.007942] Bluetooth: BNEP (Ethernet Emulation) ver 1.3 [ 12.007951] Bluetooth: BNEP filters: protocol multicast [ 12.007966] Bluetooth: BNEP socket layer initialized

[21100.863005] Bluetooth: hci0: command 0x200c tx timeout [21103.022987] Bluetooth: hci0: command 0x200c tx timeout [21103.023510] Bluetooth: hci0: Frame reassembly failed (-84) [21105.103026] Bluetooth: hci0: command 0x200b tx timeout

pelwell commented 5 years ago

After following my instructions earlier you should have had a file like this:

...

if [ "$uart0" = "$serial1" ] ; then
    uart0_pins="`wc -c /proc/device-tree/soc/gpio@7e200000/uart0_pins/brcm\,pins | cut -f 1 -d ' '`"
    if [ "$uart0_pins" = "16" ] ; then
        # This line is necessary to sort out the flow control pins
        stty -F /dev/serial1 115200 raw -echo
        $HCIATTACH /dev/serial1 bcm43xx 3000000 flow - $BDADDR
    else
        $HCIATTACH /dev/serial1 bcm43xx 460800 noflow - $BDADDR
    fi
else
    $HCIATTACH /dev/serial1 bcm43xx 460800 noflow - $BDADDR
fi

where the first 460800 used to say 921600. If you haven't tried that yet, please do so. If you have tried that, please change that first 460800 (or 921600 if you've changed it back) into 115200 and try again. It should look like this:

...

if [ "$uart0" = "$serial1" ] ; then
    uart0_pins="`wc -c /proc/device-tree/soc/gpio@7e200000/uart0_pins/brcm\,pins | cut -f 1 -d ' '`"
    if [ "$uart0_pins" = "16" ] ; then
        # This line is necessary to sort out the flow control pins
        stty -F /dev/serial1 115200 raw -echo
        $HCIATTACH /dev/serial1 bcm43xx 3000000 flow - $BDADDR
    else
        $HCIATTACH /dev/serial1 bcm43xx 115200 noflow - $BDADDR
    fi
else
    $HCIATTACH /dev/serial1 bcm43xx 460800 noflow - $BDADDR
fi
furiaceka87 commented 5 years ago

Thanks, I try first with 460800 and later with 115200 and I let you know the status after few hours. Meanwhile I've updated in my message above some information about my configuration

milou161185 commented 5 years ago

I made the change as requested and I have no more errors. can this change have other impacts?

pelwell commented 5 years ago

It reduces the maximum data rate you can send over Bluetooth, but I don't think your application requires a high bandwidth. It will have no effect on anything else.

It seems that a change between the 4.14 and 4.19 kernel has affected scheduling in a way that makes it more likely that some UART data is dropped because the ARM can't empty the UART FIFO in time. By halving the baud rate we are doubling the amount of time available to respond, making data loss much less likely.

milou161185 commented 5 years ago

ok, thank you so much for your help and your reactivity !!

pelwell commented 5 years ago

For applications where Bluetooth reliability is important I would recommend a Zero W, 3B+ or 4B, but I understand why changing now might not appeal.

milou161185 commented 5 years ago

I will watch the price of 4 or at least 3+ right now!

pelwell commented 5 years ago

Some people use external USB dongles - just search for "usb bluetooth dongle for raspberry pi".

J-Luc16 commented 5 years ago 
  $HCIATTACH /dev/serial1 bcm43xx 3000000 flow - $BDADDR

else $HCIATTACH /dev/serial1 bcm43xx 115200 noflow - $BDADDR fi

115200 is perfect for me too (telemetry) and seems to work like a charm. I have cancelled the kernel hack and put back the last kernel, all is working perfectly until now.

Thanks a lot !

PS : the external dongle solved, obviously, the issue but as my Pi is a PI3, the goal was to use it "naked".

pymumu commented 5 years ago

same problem

Pickel commented 5 years ago

pelwell could you clarify the gain in going from a 3B to a 3B+ in this regard? I cannot see the difference in architecture on the bluetooth side or is the clock difference the point here?

popcornmix commented 5 years ago

pelwell could you clarify the gain in going from a 3B to a 3B+ in this regard? I cannot see the difference in architecture on the bluetooth side or is the clock difference the point here?

From earlier in this issue:

Unlike the later Bluetooth Pis, Pi 3B doesn't have flow control signals to the Bluetooth modem which means it can lose data under load

pymumu commented 5 years ago

This issue seems to only occur in system that upgraded from stretch.

Eistee82 commented 5 years ago

Is this the solution? https://forum.fhem.de/index.php/topic,75559.msg980043.html#msg980043

pelwell commented 5 years ago

That (German) forum post contains my suggestion from a few comments back (https://github.com/raspberrypi/firmware/issues/1150#issuecomment-518648032) that on a 3B you may benefit from reducing the baud rate to the BT modem. This is only going to be acceptable if your application doesn't require a high data throughput.

risa2000 commented 4 years ago

Just a heads up for anyone facing this issue.

I did the mod of /usr/bin/btuart suggested by @pelwell and it was fine until some recent system update, which apparently overwrote the file. I am not sure if it was a full distro upgrade (Stretch -> Buster) or just a regular apt-get dist-upgrade, but I had to rewrite it again.

Unfortunately I noticed that only after I saw some BT failures, which did not recover.

akomelj commented 4 years ago

This issue seems to only occur in system that upgraded from stretch.

Not really. Fresh Buster install here...

lucagiove commented 4 years ago 
  $HCIATTACH /dev/serial1 bcm43xx 460800 noflow - $BDADDR

Did the change on HassOS with Raspberry 3 and seems to work

lucagiove commented 4 years ago

@pelwell there are lots of complains on bluetooth problems with Raspberry 3 for many different sensors in home assistant other with raspbian. Do you think it's kernel or firmware related? Don'y you think would be better to submit a patch to btuart in order to reduce the baudrate?