klali / ha-plejd

Plejd component for Home Assistant
Apache License 2.0
69 stars 15 forks source link

ha-plejd not working on RPI/ Bluetooth needing restart #38

Closed Emlben closed 3 years ago

Emlben commented 3 years ago

Hi, this has stopped working for me.

I am getting this in my home assistant log. Can that be related somehow? 2021-01-11 10:20:04 WARNING (MainThread) [homeassistant.components.light] Light is deprecated, modify PlejdLight to extend LightEntity 2021-01-11 10:20:15 WARNING (MainThread) [homeassistant.components.light] Setup of light platform plejd is taking over 10 seconds. 2021-01-11 10:21:05 ERROR (MainThread) [homeassistant.components.light] Setup of platform plejd is taking longer than 60 seconds. Startup will proceed without waiting any longer.

Latest ha-plejd hass 2021.1.1

klali commented 3 years ago

I don't think it's related to LightEntity, that deprecation has been around for some time.

Can you turn on debug for the plejd platform and see if you get more interesting things in the log?

Emlben commented 3 years ago

All lines showing up that contains word plejd, in the order, they appear: INFO (MainThread) [homeassistant.components.light] Setting up light.plejd DEBUG (MainThread) [custom_components.plejd.light] Discovered bluetooth adapter /org/bluez/hci0 DEBUG (MainThread) [customcomponents.plejd.light] Disconnecting/org/bluez/hci0/dev{my mac-address} (appears 4 seconds after discovering) WARNING (MainThread) [homeassistant.components.light] Setup of light platform plejd is taking over 10 seconds. ERROR (MainThread) [homeassistant.components.light] Setup of platform plejd is taking longer than 60 seconds. Startup will proceed without waiting any longer.

Anything that makes any sense? Anything else I should be looking for?

Emlben commented 3 years ago

Update:

DEBUG (MainThread) [customcomponents.plejd.light] Disconnecting/org/bluez/hci0/dev{my mac-address} (appears 4 seconds after discovering)

{my mac-address} stands for the mac-address of one of my plejd units. That unit and several other plejd units are showing up if I do a hcitool lescan (from inside my hass docker container) I have tried to reboot that single plejd unit as well

klali commented 3 years ago

Odd, so probably the disconnect hanging or discovery not properly starting. Did you restart the machine as well? I think it's likelier that the adapter/bluez/dbus being sad than the plejd unit.

I'll upgrade to similar home-assistant version when I have a chance and see how it behaves for me.

Emlben commented 3 years ago

Did you restart the machine as well? I think it's likelier that the adapter/bluez/dbus being sad than the plejd unit.

So you say I should destroy my beautiful uptime since September 14:th? ;)

Ok, I just need to rescue some configurations from my Grafana docker container since I did not provide it with any persistent disk space when I created it and have done quite a lot work creating different views. I´ll let you know afterwards.

klali commented 3 years ago

I don't like the restart option personally because it doesn't really tell us what's wrong. I've seen oddities with the bluetooth controller getting sad and either restart or re-loading the kernel modules have helped then.

Emlben commented 3 years ago

re-loading the kernel modules have helped then.

What kernel modules? I mean I could try to reload them one at a time and restart hass in between trying to narrow down the possible root causes.

Emlben commented 3 years ago

Found something that might be interesting in the dmesg-log: (Sorry about the bad formatting)

[Jan 4 12:06] debugfs: Directory '64' with parent 'hci0' already present! [ +0.000030] sysfs: cannot create duplicate filename '/devices/platform/soc/fe201000.serial/tty/ttyAMA0/hci0/hci0:64' [ +0.000008] CPU: 2 PID: 2258 Comm: kworker/u9:2 Tainted: G C 5.4.51-v7l+ #1327 [ +0.000003] Hardware name: BCM2711 [ +0.000056] Workqueue: hci0 hci_rx_work [bluetooth] [ +0.000004] Backtrace: [ +0.000013] [<c020d46c>] (dump_backtrace) from [<c020d768>] (show_stack+0x20/0x24) [ +0.000006] r6:c2402000 r5:00000000 r4:c129c8f8 r3:c6a7d799 [ +0.000008] [<c020d748>] (show_stack) from [<c0a39a24>] (dump_stack+0xe0/0x124) [ +0.000009] [<c0a39944>] (dump_stack) from [<c0497774>] (sysfs_warn_dup+0x68/0x74) [ +0.000005] r8:d1cab40c r7:d5c88120 r6:d5c88120 r5:c82d9340 r4:d401e000 r3:c6a7d799 [ +0.000005] [<c049770c>] (sysfs_warn_dup) from [<c04978c8>] (sysfs_create_dir_ns+0xf0/0x104) [ +0.000005] r6:ffffffef r5:c1204f88 r4:d1cab588 r3:0000000c [ +0.000006] [<c04977d8>] (sysfs_create_dir_ns) from [<c0a3fdf0>] (kobject_add_internal+0xb8/0x324) [ +0.000005] r7:c126ef60 r6:d633a968 r5:d1cab588 r4:d1cab588 [ +0.000006] [<c0a3fd38>] (kobject_add_internal) from [<c0a40268>] (kobject_add+0x60/0xb8) [ +0.000005] r8:d1cab40c r7:d633a968 r6:00000000 r5:d1cab588 r4:c1204f88 [ +0.000007] [<c0a40208>] (kobject_add) from [<c075b11c>] (device_add+0xfc/0x5f0) [ +0.000003] r3:00000007 r2:00000000 [ +0.000004] r7:d633a968 r6:c1204f88 r5:d633a000 r4:d1cab588 [ +0.000043] [<c075b020>] (device_add) from [<bf544150>] (hci_conn_add_sysfs+0x40/0x6c [bluetooth]) [ +0.000005] r9:00000001 r8:d1cab40c r7:d633a008 r6:d633a01c r5:d633a000 r4:d1cab588 [ +0.000078] [<bf544110>] (hci_conn_add_sysfs [bluetooth]) from [<bf52f0fc>] (le_conn_complete_evt+0x310/0x5b0 [bluetooth]) [ +0.000004] r6:00000001 r5:c1204f88 r4:d633a000 r3:c6a7d799 [ +0.000075] [<bf52edec>] (le_conn_complete_evt [bluetooth]) from [<bf52f67c>] (hci_le_meta_evt+0x2e0/0xa30 [bluetooth]) [ +0.000006] r10:c1204f88 r9:d633a008 r8:00000000 r7:d633a7dc r6:d1caac0a r5:d633a000 [ +0.000003] r4:d57a00c0 [ +0.000075] [<bf52f39c>] (hci_le_meta_evt [bluetooth]) from [<bf531524>] (hci_event_packet+0x9fc/0x2f44 [bluetooth]) [ +0.000005] r10:c1204f88 r9:d633a008 r8:00000000 r7:d633a7dc r6:0000003d r5:d57a00c0 [ +0.000003] r4:d633a000 [ +0.000074] [<bf530b28>] (hci_event_packet [bluetooth]) from [<bf522c9c>] (hci_rx_work+0x184/0x250 [bluetooth]) [ +0.000005] r10:d57a00c0 r9:d633a008 r8:00000000 r7:d633a7dc r6:d633a000 r5:d633a8a8 [ +0.000003] r4:d633a704 [ +0.000042] [<bf522b18>] (hci_rx_work [bluetooth]) from [<c023e224>] (process_one_work+0x17c/0x4b4) [ +0.000005] r10:00000000 r9:00000120 r8:00000000 r7:d8119900 r6:efb2fc00 r5:c2bbfc00 [ +0.000004] r4:d633a704 [ +0.000007] [<c023e0a8>] (process_one_work) from [<c023ea8c>] (worker_thread+0x54/0x5b4) [ +0.000005] r10:c2bbfc00 r9:c2402038 r8:c1203d00 r7:efb2fc18 r6:00000088 r5:c2bbfc14 [ +0.000003] r4:efb2fc00 [ +0.000007] [<c023ea38>] (worker_thread) from [<c0244e70>] (kthread+0x13c/0x168) [ +0.000005] r10:d48cad5c r9:d872be74 r8:c023ea38 r7:c2bbfc00 r6:00000000 r5:c2d0b0c0 [ +0.000003] r4:d48cad40 [ +0.000006] [<c0244d34>] (kthread) from [<c02010ac>] (ret_from_fork+0x14/0x28) [ +0.000003] Exception stack(0xc2403fb0 to 0xc2403ff8) [ +0.000005] 3fa0: 00000000 00000000 00000000 00000000 [ +0.000005] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ +0.000004] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000 [ +0.000005] r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0244d34 [ +0.000003] r4:c2d0b0c0 r3:40000700 [ +0.000015] kobject_add_internal failed for hci0:64 with -EEXIST, don't try to register things with the same name in the same directory. [ +0.000006] Bluetooth: hci0: failed to register connection device

Emlben commented 3 years ago

I am running hass in docker on Raspian with graphical desktop available. Now I turned off and then on Bluetooth from the desktop GUI and the restarted hass. This is the dmesg-log output from that: [Jan12 09:13] debugfs: File 'le_min_key_size' in directory 'hci0' already present! [ +0.000016] debugfs: File 'le_max_key_size' in directory 'hci0' already present! Afterwards everything is working again,

I previously restarted the bluetooth service with $ sudo /etc/init.d/bluetooth restart, that did not help anything,

I am closing this issue now, thank you for your support!