SOMA Blind fails to open/close

shababa0 commented 3 years ago

Trying to open or close the blinds fails; Home app just goes back to showing the previous state


[10/25/2021, 6:30:41 PM] [SOMA] Bedroom: set Received Signal Strength Indication from -88 to -90
[10/25/2021, 6:30:55 PM] [SOMA] Bedroom: Target Position changed from 100% to 0%
[10/25/2021, 6:30:56 PM] [SOMA] Bedroom: set position from 0 to 100
[10/25/2021, 6:30:56 PM] [SOMA] Bedroom: set Position State from 2 to 0
[10/25/2021, 6:30:56 PM] [SOMA] Bedroom: error: RangeError: motorService: unknown service key
    at SomaPeripheral.write (/usr/lib/node_modules/homebridge-soma/lib/BleClient.js:617:13)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)
[10/25/2021, 6:30:56 PM] [SOMA] Bedroom: request 6: discoverAllServicesAndCharacteristics
[10/25/2021, 6:30:56 PM] [SOMA] Bedroom: warning: request 6: disconnected unexpectedly
[10/25/2021, 6:30:56 PM] [SOMA] Bedroom: warning: polling: failed
[10/25/2021, 6:30:57 PM] [SOMA] Bedroom: set position from 100 to 0
[10/25/2021, 6:30:57 PM] [SOMA] Bedroom: set Target Position from 0% to 100%
[10/25/2021, 6:30:57 PM] [SOMA] Bedroom: set Position State from 0 to 2
[10/25/2021, 6:31:02 PM] [SOMA] Bedroom: polling
[10/25/2021, 6:31:03 PM] [SOMA] Bedroom: Target Position changed from 100% to 0%
[10/25/2021, 6:31:03 PM] [SOMA] Bedroom: set Received Signal Strength Indication from -90 to -91
[10/25/2021, 6:31:03 PM] [SOMA] Bedroom: set position from 0 to 100
[10/25/2021, 6:31:03 PM] [SOMA] Bedroom: set Position State from 2 to 0
[10/25/2021, 6:31:03 PM] [SOMA] Bedroom: error: RangeError: motorService: unknown service key
    at SomaPeripheral.write (/usr/lib/node_modules/homebridge-soma/lib/BleClient.js:617:13)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)
[10/25/2021, 6:31:03 PM] [SOMA] Bedroom: request 9: discoverAllServicesAndCharacteristics
[10/25/2021, 6:31:03 PM] [SOMA] Bedroom: warning: request 9: disconnected unexpectedly
[10/25/2021, 6:31:03 PM] [SOMA] Bedroom: warning: polling: failed

shababa0 commented 3 years ago

homebridge-soma v1.0.2 installed

ebaauw commented 3 years ago

[10/25/2021, 6:30:56 PM] [SOMA] Bedroom: request 6: discoverAllServicesAndCharacteristics [10/25/2021, 6:30:56 PM] [SOMA] Bedroom: warning: request 6: disconnected unexpectedly [10/25/2021, 6:30:56 PM] [SOMA] Bedroom: warning: polling: failed

Looks like Homebridge SOMA cannot get the device services and characteristics, so it never initialises it properly. I should fix the RangeError, but that won’t solve your issue.

[10/25/2021, 6:31:03 PM] [SOMA] Bedroom: set Received Signal Strength Indication from -90 to -91

As you can see in the log, the RSSI for this device is around -90, which likely is too weak for a stable connection. Are you running Homebridge on a Raspberry Pi? If so, try moving the Pi closer to the blinds, with a clear line of sight to them. Place the Pi, so the bluetooth antenna (near the uSD card reader) faces the blinds. Using a metal (heat sink) case might deteriorate the bluetooth signal.

ebaauw commented 3 years ago

[10/25/2021, 6:31:03 PM] [SOMA] Bedroom: error: RangeError: motorService: unknown service key

Unfortunately, this bug might still appear in v1.0.3. I might be for a different service, or even for an unknown characteristic key. I happens when not all services and/or characteristics are discovered on the initial connect. Unfortunately, noble gives no clue when this happens, so I need to refactor the initialisation logic to check for all whitelisted services and characteristics.

This will take me some time. For now, the only workaround is restarting Homebridge SOMA, until all SOMA devices are polled successfully at least once.

shababa0 commented 3 years ago

Thanks for taking a look. Combination of multiple reboots and moving the homebridge got it working again.

ebaauw commented 3 years ago

I still hope I can eliminate the need for the reboots. The “moving of the homebridge”, or rather the antenna of the bluetooth radio used by Homebridge SOMA is something I can do little about. I’ve been searching the Internet about attaching an external antenna to a Raspberry Pi, but that involves airflow soldering for which I don’t have the right equipment. The Pi Zero W onboard antenna seems to do better than a Pi 4B with heatsink case, but its CPU isn’t quite powerful enough. My initial testing with the Pi Zero 2 W yields promising results. I tried a USB bluetooth adapter, but the device I ordered seems DOA. It’s recognised alright, but doesn’t receive anything. And noble doesn’t do anything at all on macOS Monterey.

washcroft commented 3 years ago

I’ve been searching the Internet about attaching an external antenna to a Raspberry Pi, but that involves airflow soldering for which I don’t have the right equipment. The Pi Zero W onboard antenna seems to do better than a Pi 4B with heatsink case, but its CPU isn’t quite powerful enough. My initial testing with the Pi Zero 2 W yields promising results. I tried a USB bluetooth adapter, but the device I ordered seems DOA. It’s recognised alright, but doesn’t receive anything. And noble doesn’t do anything at all on macOS Monterey.

I've had good results by disabling onboard Bluetooth and instead using the TP-Link UB500 Nano dongle, or the LM1010-0972 (which has a proper external whip antenna). I now don't have any issues with signal strength (but I do still have the issues discussed on Discord to do with multiple devices being controlled at the same time).

ebaauw commented 3 years ago

Thanks @washcroft. I cannot find the LM1010-0972 in Europe, but ordered the TP-Link UB500.

washcroft commented 3 years ago

Thanks @washcroft. I cannot find the LM1010-0972 in Europe, but ordered the TP-Link UB500.

I got mine from Farnell in the UK, not sure if they will ship to or have a presence in your country?

https://uk.farnell.com/lm-technologies/lm1010-0972/bluetooth-adapter-w-antenna-v4/dp/2946819

UB500 gave similar results though 👍

ebaauw commented 3 years ago

Thanks, again. They refer to their Dutch side, which only delivers to companies, but refers to their partner for private individuals. Found the device, at almost EUR 40 plus shipping. I’ll try the TP-Link first.

ebaauw commented 3 years ago

@washcroft hope you don't mind me reaching out to you here.

I received the UB500 and confirmed it's working on Windows 10. It's recognised by the Raspberry Pi as hci1, and hciconfig seems happy about it. However, sudo hcitool -i hci1 lescan doesn't seem to do anything. Did you do anything special to support the UB500? How did you disable the onboard Bluetooth adapter? Simply through rfkill or by disabling the kernel driver for it?

washcroft commented 3 years ago

@washcroft hope you don't mind me reaching out to you here.

I received the UB500 and confirmed it's working on Windows 10. It's recognised by the Raspberry Pi as hci1, and hciconfig seems happy about it. However, sudo hcitool -I hci1 lesson doesn't seem to do anything. Did you do anything special to support the UB500? How did you disable the onboard Bluetooth adapter? Simply through rfkill or by disabling the kernel driver for it?

Not at all.

To disable onboard bluetooth I added dtoverlay=disable-bt to /boot/config.txt, and

blacklist btbcm
blacklist hci_uart

to /etc/modprobe.d/raspi-blacklist.conf.

hci0 is then my external dongle, and lescan works fine through it.

ebaauw commented 3 years ago

Thanks. I must be missing something; even with those changes, after a reboot, lescan still doesn't yield anything. Are you on 32-bit PiOS buster? What model Pi are you using?

washcroft commented 3 years ago

Thanks. I must be missing something; even with those changes, after a reboot, lescan still doesn't yield anything. Are you on 32-bit PiOS buster? What model Pi are you using?

Pi 4B running 32-bit Buster

Here's some running info from mine if it helps you spot any differences:

root@raspberrypi-main:~# uname -a
Linux raspberrypi-main 5.10.63-v7l+ #1459 SMP Wed Oct 6 16:41:57 BST 2021 armv7l GNU/Linux

root@raspberrypi-main:~# cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

root@raspberrypi-main:~# lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 003: ID 0a12:0001 Cambridge Silicon Radio, Ltd Bluetooth Dongle (HCI mode)
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

root@raspberrypi-main:~# lsmod
Module                  Size  Used by
xt_conntrack           16384  1
xt_MASQUERADE          16384  1
nf_conntrack_netlink    49152  0
nft_counter            16384  15
xt_addrtype            16384  2
nft_compat             20480  4
nft_chain_nat          16384  4
nf_nat                 49152  2 xt_MASQUERADE,nft_chain_nat
nf_conntrack          139264  4 xt_MASQUERADE,nf_conntrack_netlink,xt_conntrack,nf_nat
nf_defrag_ipv6         20480  1 nf_conntrack
nf_defrag_ipv4         16384  1 nf_conntrack
nf_tables             196608  45 nft_compat,nft_chain_nat,nft_counter
nfnetlink              16384  4 nft_compat,nf_conntrack_netlink,nf_tables
br_netfilter           32768  0
bridge                163840  1 br_netfilter
bnep                   20480  2
overlay               106496  0
sha256_generic         16384  0
cfg80211              761856  0
8021q                  32768  0
garp                   16384  1 8021q
stp                    16384  2 garp,bridge
llc                    16384  3 garp,bridge,stp
btusb                  49152  0
btrtl                  16384  1 btusb
btintel                24576  1 btusb
btbcm                  16384  1 btusb
bluetooth             393216  26 btrtl,btintel,bnep,btbcm,btusb
ecdh_generic           16384  1 bluetooth
ecc                    40960  1 ecdh_generic
rfkill                 32768  4 bluetooth,cfg80211
bcm2835_isp            32768  0
snd_bcm2835            24576  1
bcm2835_v4l2           40960  0
bcm2835_codec          40960  0
snd_pcm               110592  1 snd_bcm2835
bcm2835_mmal_vchiq     32768  3 bcm2835_isp,bcm2835_codec,bcm2835_v4l2
v4l2_mem2mem           36864  1 bcm2835_codec
videobuf2_vmalloc      16384  1 bcm2835_v4l2
videobuf2_dma_contig    20480  2 bcm2835_isp,bcm2835_codec
snd_timer              32768  1 snd_pcm
videobuf2_memops       16384  2 videobuf2_dma_contig,videobuf2_vmalloc
videobuf2_v4l2         32768  4 bcm2835_isp,bcm2835_codec,bcm2835_v4l2,v4l2_mem2mem
videobuf2_common       61440  5 bcm2835_isp,bcm2835_codec,bcm2835_v4l2,v4l2_mem2mem,videobuf2_v4l2
snd                    77824  5 snd_timer,snd_bcm2835,snd_pcm
videodev              249856  6 bcm2835_isp,bcm2835_codec,videobuf2_common,bcm2835_v4l2,v4l2_mem2mem,videobuf2_v4l2
mc                     45056  6 bcm2835_isp,bcm2835_codec,videobuf2_common,videodev,v4l2_mem2mem,videobuf2_v4l2
vc_sm_cma              32768  2 bcm2835_isp,bcm2835_mmal_vchiq
raspberrypi_hwmon      16384  0
rpivid_mem             16384  0
rpi_poe_fan            16384  0
nvmem_rmem             16384  0
uio_pdrv_genirq        16384  0
uio                    20480  1 uio_pdrv_genirq
i2c_dev                20480  0
ip_tables              28672  0
x_tables               32768  5 ip_tables,nft_compat,xt_MASQUERADE,xt_addrtype,xt_conntrack
ipv6                  495616  30 br_netfilter,bridge

root@raspberrypi-main:~# dmesg
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.10.63-v7l+ (dom@buildbot) (arm-linux-gnueabihf-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1459 SMP Wed Oct 6 16:41:57 BST 2021
[    0.000000] CPU: ARMv7 Processor [410fd083] revision 3 (ARMv7), cr=30c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 4 Model B Rev 1.4
[    0.000000] random: fast init done
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] Reserved memory: created CMA memory pool at 0x000000002ac00000, size 64 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000000000-0x000000002fffffff]
[    0.000000]   Normal   empty
[    0.000000]   HighMem  [mem 0x0000000030000000-0x00000001ffffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x000000003b3fffff]
[    0.000000]   node   0: [mem 0x0000000040000000-0x00000000fbffffff]
[    0.000000]   node   0: [mem 0x0000000100000000-0x00000001ffffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff]
[    0.000000] On node 0 totalpages: 2061312
[    0.000000]   DMA zone: 1728 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 196608 pages, LIFO batch:63
[    0.000000]   HighMem zone: 1864704 pages, LIFO batch:63
[    0.000000] percpu: Embedded 20 pages/cpu s50828 r8192 d22900 u81920
[    0.000000] pcpu-alloc: s50828 r8192 d22900 u81920 alloc=20*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 2059584
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=0 bcm2708_fb.fbheight=0 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:E2:48:E4 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyAMA0,115200 console=tty1 root=PARTUUID=c6a6cb95-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait quiet splash plymouth.ignore-serial-consoles spidev.bufsiz=8192
[    0.000000] Kernel parameter elevator= does not have any effect anymore.
               Please use sysfs to set IO scheduler for individual devices.
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] software IO TLB: mapped [mem 0x0000000022400000-0x0000000026400000] (64MB)
[    0.000000] Memory: 8021224K/8245248K available (10240K kernel code, 1364K rwdata, 3192K rodata, 2048K init, 891K bss, 158488K reserved, 65536K cma-reserved, 7458816K highmem)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 34315 entries in 68 pages
[    0.000000] ftrace: allocated 68 pages with 2 groups
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000]  Rude variant of Tasks RCU enabled.
[    0.000000]  Tracing variant of Tasks RCU enabled.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] random: get_random_bytes called from start_kernel+0x3c8/0x59c with crng_init=1
[    0.000007] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483647500ns
[    0.000026] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275 ns
[    0.000086] bcm2835: system timer (irq = 25)
[    0.000733] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[    0.000751] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.000769] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000784] Switching to timer-based delay loop, resolution 18ns
[    0.001039] Console: colour dummy device 80x30
[    0.001109] printk: console [tty1] enabled
[    0.001165] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000)
[    0.001197] pid_max: default: 32768 minimum: 301
[    0.001362] LSM: Security Framework initializing
[    0.001546] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.001572] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.003026] cgroup: Disabling memory control group subsystem
[    0.003257] CPU: Testing write buffer coherency: ok
[    0.003717] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.004930] Setting up static identity map for 0x200000 - 0x20003c
[    0.005127] rcu: Hierarchical SRCU implementation.
[    0.006055] smp: Bringing up secondary CPUs ...
[    0.007256] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.008617] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.009904] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.010063] smp: Brought up 1 node, 4 CPUs
[    0.010084] SMP: Total of 4 processors activated (432.00 BogoMIPS).
[    0.010108] CPU: All CPU(s) started in HYP mode.
[    0.010122] CPU: Virtualization extensions available.
[    0.011015] devtmpfs: initialized
[    0.025761] VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0
[    0.025978] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.026008] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.027876] pinctrl core: initialized pinctrl subsystem
[    0.028918] NET: Registered protocol family 16
[    0.033038] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.033804] audit: initializing netlink subsys (disabled)
[    0.034065] audit: type=2000 audit(0.030:1): state=initialized audit_enabled=0 res=1
[    0.034631] thermal_sys: Registered thermal governor 'step_wise'
[    0.035731] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.035748] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.036146] Serial: AMBA PL011 UART driver
[    0.066075] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[    0.080816] raspberrypi-firmware soc:firmware: Attached to firmware from 2021-09-30T19:21:03, variant start
[    0.090829] raspberrypi-firmware soc:firmware: Firmware hash is 51215b4f6e3966401ecd99652a35cf1c25069113
[    0.132396] Kprobes globally optimized
[    0.137431] bcm2835-dma fe007000.dma: DMA legacy API manager, dmachans=0x1
[    0.141594] vgaarb: loaded
[    0.142047] SCSI subsystem initialized
[    0.142264] usbcore: registered new interface driver usbfs
[    0.142325] usbcore: registered new interface driver hub
[    0.142397] usbcore: registered new device driver usb
[    0.142754] usb_phy_generic phy: supply vcc not found, using dummy regulator
[    0.144787] clocksource: Switched to clocksource arch_sys_counter
[    1.103321] VFS: Disk quotas dquot_6.6.0
[    1.103417] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.103579] FS-Cache: Loaded
[    1.103807] CacheFiles: Loaded
[    1.114265] NET: Registered protocol family 2
[    1.114503] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
[    1.116112] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[    1.116246] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[    1.116311] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    1.116383] TCP: Hash tables configured (established 8192 bind 8192)
[    1.116544] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    1.116581] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    1.116845] NET: Registered protocol family 1
[    1.117578] RPC: Registered named UNIX socket transport module.
[    1.117594] RPC: Registered udp transport module.
[    1.117609] RPC: Registered tcp transport module.
[    1.117624] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.117649] PCI: CLS 0 bytes, default 64
[    1.120669] Initialise system trusted keyrings
[    1.120901] workingset: timestamp_bits=14 max_order=21 bucket_order=7
[    1.129279] zbud: loaded
[    1.131455] FS-Cache: Netfs 'nfs' registered for caching
[    1.132217] NFS: Registering the id_resolver key type
[    1.132266] Key type id_resolver registered
[    1.132281] Key type id_legacy registered
[    1.132418] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    1.132435] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[    1.133484] Key type asymmetric registered
[    1.133501] Asymmetric key parser 'x509' registered
[    1.133693] bounce: pool size: 64 pages
[    1.133737] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    1.133945] io scheduler mq-deadline registered
[    1.133961] io scheduler kyber registered
[    1.138329] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[    1.138361] brcm-pcie fd500000.pcie:   No bus range found for /scb/pcie@7d500000, using [bus 00-ff]
[    1.138442] brcm-pcie fd500000.pcie:      MEM 0x0600000000..0x063fffffff -> 0x00c0000000
[    1.138531] brcm-pcie fd500000.pcie:   IB MEM 0x0000000000..0x00bfffffff -> 0x0400000000
[    1.196890] brcm-pcie fd500000.pcie: link up, 5.0 GT/s PCIe x1 (SSC)
[    1.197279] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[    1.197300] pci_bus 0000:00: root bus resource [bus 00-ff]
[    1.197321] pci_bus 0000:00: root bus resource [mem 0x600000000-0x63fffffff] (bus address [0xc0000000-0xffffffff])
[    1.197411] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[    1.197654] pci 0000:00:00.0: PME# supported from D0 D3hot
[    1.201212] PCI: bus0: Fast back to back transfers disabled
[    1.201551] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[    1.201679] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[    1.202114] pci 0000:01:00.0: PME# supported from D0 D3hot
[    1.205690] PCI: bus1: Fast back to back transfers disabled
[    1.205787] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[    1.205812] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[    1.205894] pci 0000:00:00.0: PCI bridge to [bus 01]
[    1.205919] pci 0000:00:00.0:   bridge window [mem 0x600000000-0x6000fffff]
[    1.206323] pcieport 0000:00:00.0: enabling device (0140 -> 0142)
[    1.206538] pcieport 0000:00:00.0: PME: Signaling with IRQ 60
[    1.207458] bcm2708_fb soc:fb: Unable to determine number of FBs. Disabling driver.
[    1.207509] bcm2708_fb: probe of soc:fb failed with error -2
[    1.212892] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    1.215857] iproc-rng200 fe104000.rng: hwrng registered
[    1.216145] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    1.217031] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[    1.229296] brd: module loaded
[    1.241567] loop: module loaded
[    1.243303] Loading iSCSI transport class v2.0-870.
[    1.246628] libphy: Fixed MDIO Bus: probed
[    1.248281] bcmgenet fd580000.ethernet: GENET 5.0 EPHY: 0x0000
[    1.264865] libphy: bcmgenet MII bus: probed
[    1.344974] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus
[    1.346147] usbcore: registered new interface driver r8152
[    1.346216] usbcore: registered new interface driver lan78xx
[    1.346276] usbcore: registered new interface driver smsc95xx
[    1.394072] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    1.394108] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[    1.397407] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000060000000890
[    1.398739] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.10
[    1.398759] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.398776] usb usb1: Product: xHCI Host Controller
[    1.398793] usb usb1: Manufacturer: Linux 5.10.63-v7l+ xhci-hcd
[    1.398809] usb usb1: SerialNumber: 0000:01:00.0
[    1.399537] hub 1-0:1.0: USB hub found
[    1.399648] hub 1-0:1.0: 1 port detected
[    1.400332] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    1.400360] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[    1.400385] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    1.400887] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.10
[    1.400906] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.400923] usb usb2: Product: xHCI Host Controller
[    1.400940] usb usb2: Manufacturer: Linux 5.10.63-v7l+ xhci-hcd
[    1.400956] usb usb2: SerialNumber: 0000:01:00.0
[    1.401669] hub 2-0:1.0: USB hub found
[    1.401754] hub 2-0:1.0: 4 ports detected
[    1.403383] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    1.403678] dwc_otg: FIQ enabled
[    1.403693] dwc_otg: NAK holdoff enabled
[    1.403708] dwc_otg: FIQ split-transaction FSM enabled
[    1.403726] Module dwc_common_port init
[    1.404181] usbcore: registered new interface driver uas
[    1.404292] usbcore: registered new interface driver usb-storage
[    1.404500] mousedev: PS/2 mouse device common for all mice
[    1.406210] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    1.409555] sdhci: Secure Digital Host Controller Interface driver
[    1.409571] sdhci: Copyright(c) Pierre Ossman
[    1.410150] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.413542] ledtrig-cpu: registered to indicate activity on CPUs
[    1.413908] hid: raw HID events driver (C) Jiri Kosina
[    1.414094] usbcore: registered new interface driver usbhid
[    1.414108] usbhid: USB HID core driver
[    1.420033] Initializing XFRM netlink socket
[    1.420075] NET: Registered protocol family 17
[    1.420183] Key type dns_resolver registered
[    1.420701] Registering SWP/SWPB emulation handler
[    1.420868] registered taskstats version 1
[    1.420896] Loading compiled-in X.509 certificates
[    1.421756] Key type ._fscrypt registered
[    1.421771] Key type .fscrypt registered
[    1.421787] Key type fscrypt-provisioning registered
[    1.434556] uart-pl011 fe201000.serial: there is not valid maps for state default
[    1.434883] uart-pl011 fe201000.serial: cts_event_workaround enabled
[    1.434962] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 36, base_baud = 0) is a PL011 rev2
[    1.442804] printk: console [ttyAMA0] enabled
[    1.449492] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    1.454004] of_cfs_init
[    1.454273] of_cfs_init: OK
[    1.487508] mmc0: SDHCI controller on fe340000.mmc [fe340000.mmc] using ADMA
[    1.488154] Waiting for root device PARTUUID=c6a6cb95-02...
[    1.591489] mmc0: new ultra high speed DDR50 SDXC card at address aaaa
[    1.592415] mmcblk0: mmc0:aaaa SP64G 59.5 GiB
[    1.594370]  mmcblk0: p1 p2 p3 p4
[    1.614311] EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
[    1.614330] EXT4-fs (mmcblk0p2): write access will be enabled during recovery
[    1.684835] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[    1.709502] EXT4-fs (mmcblk0p2): recovery complete
[    1.710994] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    1.711071] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    1.711854] devtmpfs: mounted
[    1.721718] Freeing unused kernel memory: 2048K
[    1.722042] Run /sbin/init as init process
[    1.722057]   with arguments:
[    1.722071]     /sbin/init
[    1.722085]     splash
[    1.722099]   with environment:
[    1.722114]     HOME=/
[    1.722128]     TERM=linux
[    1.897747] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
[    1.897769] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    1.897786] usb 1-1: Product: USB2.0 Hub
[    1.899846] hub 1-1:1.0: USB hub found
[    1.900111] hub 1-1:1.0: 4 ports detected
[    2.157761] systemd[1]: System time before build time, advancing clock.
[    2.224849] usb 1-1.1: new full-speed USB device number 3 using xhci_hcd
[    2.254557] NET: Registered protocol family 10
[    2.255991] Segment Routing with IPv6
[    2.327857] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[    2.329336] systemd[1]: Detected architecture arm.
[    2.388845] systemd[1]: Set hostname to <raspberrypi-main>.
[    2.410719] usb 1-1.1: New USB device found, idVendor=0a12, idProduct=0001, bcdDevice=88.91
[    2.410740] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.533727] uart-pl011 fe201000.serial: no DMA platform data
[    3.344065] random: systemd: uninitialized urandom read (16 bytes read)
[    3.357689] random: systemd: uninitialized urandom read (16 bytes read)
[    3.358327] systemd[1]: Listening on fsck to fsckd communication Socket.
[    3.359175] random: systemd: uninitialized urandom read (16 bytes read)
[    3.359806] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    3.362479] systemd[1]: Created slice User and Session Slice.
[    3.366389] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    3.367160] systemd[1]: Listening on udev Control Socket.
[    3.369254] systemd[1]: Created slice system-serial\x2dgetty.slice.
[    3.369435] systemd[1]: Reached target Swap.
[    3.487269] i2c /dev entries driver
[    4.071092] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    4.928273] rpivid-mem feb00000.hevc-decoder: rpivid-hevcmem initialised: Registers at 0xfeb00000 length 0x00010000
[    4.932756] rpivid-mem feb10000.rpivid-local-intc: rpivid-intcmem initialised: Registers at 0xfeb10000 length 0x00001000
[    4.940115] rpivid-mem feb20000.h264-decoder: rpivid-h264mem initialised: Registers at 0xfeb20000 length 0x00010000
[    4.945461] rpivid-mem feb30000.vp9-decoder: rpivid-vp9mem initialised: Registers at 0xfeb30000 length 0x00010000
[    5.011164] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    5.013445] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    5.013470] [vc_sm_connected_init]: start
[    5.027455] [vc_sm_connected_init]: installed successfully
[    5.037231] mc: Linux media interface: v0.10
[    5.080939] videodev: Linux video capture interface: v2.00
[    5.119111] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    5.120033] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    5.137220] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    5.141575] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    5.142568] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    5.154460] bcm2835_audio bcm2835_audio: card created with 8 channels
[    5.163029] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    5.163093] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    5.179286] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    5.179331] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    5.190024] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    5.190087] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    5.229380] bcm2835-codec bcm2835-codec: Device registered as /dev/video18
[    5.229430] bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx
[    5.315034] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[    5.385790] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[    5.390850] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[    5.395532] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[    5.397881] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[    5.397912] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[    5.397937] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[    5.397960] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[    5.397982] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[    5.401029] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[    5.594005] Bluetooth: Core ver 2.22
[    5.594118] NET: Registered protocol family 31
[    5.594137] Bluetooth: HCI device and connection manager initialized
[    5.594165] Bluetooth: HCI socket layer initialized
[    5.594188] Bluetooth: L2CAP socket layer initialized
[    5.594232] Bluetooth: SCO socket layer initialized
[    5.617462] usbcore: registered new interface driver btusb
[    5.636787] Bluetooth: hci0: unexpected event for opcode 0x0000
[    7.102598] EXT4-fs (mmcblk0p4): mounted filesystem with ordered data mode. Opts: (null)
[    7.373665] systemd[1]: Started File System Check on /dev/disk/by-partuuid/c6a6cb95-01.
[    7.383495] systemd[1]: Mounting /boot...
[    7.655903] systemd[1]: Mounted /boot.
[    9.429699] systemd[1]: Started File System Check on /dev/disk/by-partuuid/c6a6cb95-03.
[    9.439415] systemd[1]: Mounting /data-small...
[    9.515005] EXT4-fs (mmcblk0p3): mounting ext2 file system using the ext4 subsystem
[    9.523522] EXT4-fs (mmcblk0p3): mounted filesystem without journal. Opts: (null)
[    9.534571] systemd[1]: Mounted /data-small.
[    9.536382] systemd[1]: Reached target Local File Systems.
[    9.543321] systemd[1]: Starting Preprocess NFS configuration...
[    9.544307] systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.
[    9.552138] systemd[1]: Starting Log2Ram...
[    9.976954] bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay)
[    9.977475] bcmgenet fd580000.ethernet eth0: Link is Down
[   10.783786] systemd-journald[376]: Received request to flush runtime journal from PID 1
[   11.763041] 8021q: 802.1Q VLAN Support v1.8
[   11.873482] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[   11.988655] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[   12.065364] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
[   12.445092] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   12.445101] Bluetooth: BNEP filters: protocol multicast
[   12.445117] Bluetooth: BNEP socket layer initialized
[   14.154941] bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control off
[   14.154971] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   14.309989] random: crng init done
[   14.309997] random: 7 urandom warning(s) missed due to ratelimiting
[   20.012878] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[   20.017959] Bridge firewalling registered
[   20.123686] ICMPv6: process `dhcpcd' is using deprecated sysctl (syscall) net.ipv6.neigh.eth0.retrans_time - use net.ipv6.neigh.eth0.retrans_time_ms instead

ebaauw commented 3 years ago

Thanks for your help! Really appreciate that.

Bus 001 Device 003: ID 0a12:0001 Cambridge Silicon Radio, Ltd Bluetooth Dongle (HCI mode)

Is that the UB500? Mine shows:

Bus 001 Device 004: ID 2357:0604 TP-Link

and has a Realtek chip, according to hciconfig:

hci1:   Type: Primary  Bus: USB
    BD Address: E8:48:B8:C8:20:00  ACL MTU: 1021:6  SCO MTU: 255:12
    UP RUNNING 
    RX bytes:4900 acl:0 sco:0 events:289 errors:0
    TX bytes:9947 acl:0 sco:0 commands:289 errors:0
    Features: 0xff 0xff 0xff 0xfe 0xdb 0xfd 0x7b 0x87
    Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3 
    Link policy: RSWITCH HOLD SNIFF PARK 
    Link mode: SLAVE ACCEPT 
    Name: 'pi5'
    Class: 0x000000
    Service Classes: Unspecified
    Device Class: Miscellaneous, 
    HCI Version:  (0xa)  Revision: 0xb
    LMP Version:  (0xa)  Subversion: 0x8761
    Manufacturer: Realtek Semiconductor Corporation (93)

I also noted it's Bluetooth 5.1 (HCI version 0xa) where the Pi onboard Bluetooth is 5.0.

washcroft commented 3 years ago

Is that the UB500? Mine shows:

Argh! I've just checked the markings on the dongle and it shows model UB4A, which is the long range version of the UB400 (Bluetooth 4.0), so it appears I have been sent the wrong dongle and I hadn't realised until now!

So unfortunately, I cannot confirm whether the UB500 works or how it performs (sorry if you ordered based on my original advice!).

ebaauw commented 3 years ago

Don’t worry. I’ll be trying the UB400 next.

washcroft commented 3 years ago

Don’t worry. I’ll be trying the UB400 next.

Get the UB4A, long range version of the UB400 - seems to be the same chip, just higher power.

ebaauw commented 3 years ago

I just received the UB400. It works straight away after plugging it in, even with the onboard Bluetooth still enabled. Next steps: find a USB extension cable and do some RSSI measurements.

Ordered the UB4A as well, ETA tomorrow.

It would seem the TP500 needs to be whitelisted in the btusb driver, see here. I'm hoping it will eventually be supported by Raspberry Pi OS, so I'll hold on to it.

ebaauw commented 3 years ago

Now running Homebridge SOMA against the UB400. The onboard device is still enabled, but I turned off its radio using rfkill.

I'm seeing some funny messages in syslog, but Homebridge SOMA seems to work just fine.

Nov  5 10:24:06 pi3 kernel: [59273.837723] Bluetooth: hci1: request failed to create LE connection: status 0x0c
[...]
Nov  5 10:24:06 pi3 bluetoothd[3827]: No cache for C8:01:2C:5E:EE:E7

The current beta, v1.0.5-1, logs the hci device and Mac address of the adapter in use. Same for soma -D and ble -D. Set NOBLE_HCI_DEVICE_ID in the environment to 1 to select hci1 instead of hci0.

Nov  5 10:18:35 pi3 hb-service.js[4877]: [SOMA] homebridge-soma v1.0.5-1, node v16.13.0, homebridge v1.3.5, homebridge-lib v5.1.16
Nov  5 10:18:37 pi3 hb-service.js[4877]: [SOMA] running on Raspberry Pi OS on arm
Nov  5 10:18:37 pi3 hb-service.js[4877]: [SOMA] hci1 [00:1A:7D:DA:71:15] enabled

While doing some testing/playing around, I get an uneasy feeling that different Bluetooth adapters might behave differently with respect to turning off scanning when connecting to a device and number of concurrent connections supported.

Different Raspberry Pi models have different on-board adapters. Checking hciconfig -a on my Pi-s:

Model	Bluetooth	Manufacturer
Pi Zero W	4.1	Broadcom Corporation
Pi 3B	4.1	Broadcom Corporation
Pi Zero 2 W	4.2	Broadcom Corporation
Pi 3B+	5.0 *	Cypress Semiconductor Corporation
Pi 4B	5.0	Cypress Semiconductor Corporation

*The documentation for the Pi 3B+ mentions Bluetooth 4.2, but hciconfig reports 5.0 for my rev 1.3 Pi 3B+. Also found this link.

I'll see if I can log the Raspberry Pi model as well in a next Homebridge SOMA version (code is already in Homebridge RPi). I'll try and see if there's an easy way to get the info displayed by hciconfig (notably Bluetooth version and adapter manufacturer) - it's not reported by Noble.

Oh, the version of Raspberry Pi OS (and the corresponding Linux kernel) might also be of influence. I'm running the latest 32-bit buster on a Pi 4B:

Linux pi3 5.10.63-v7l+ #1459 SMP Wed Oct 6 16:41:57 BST 2021 armv7l GNU/Linux

washcroft commented 3 years ago

Thanks for this - really useful stuff. Interesting that your onboard hci device still shows up, I have two until I do those mods I mentioned to disable onboard.

You're probably right regarding behaviour varying across chips/models, I don't expect noble is going to make any effort to normalise things based on it's quirks we've seen so far.

One thing I do occasionally notice is any external dongle I'm using sometimes (not often) drops and then reattaches under a different hci numbered device, i.e. was hci0 now hci1, and nothing works until I restart homebridge as homebridge-soma keeps saying bluetooth is disabled.

NOBLE_HCI_DEVICE_ID is a good idea but wouldn't help fix those situations - I guess the default is to not specify any device and to just connect to any available one, however when connection is lost or appears to be disabled, it would be good if it could fully reinitialise noble again in case the device has been swapped?

ebaauw commented 3 years ago

By default, Noble instantiates with the default adapter on require. This is what Homebridge SOMA currently uses. The default adapter is probably the lowest available hci device. Noble does provide a way to instantiate manually, specifying hci device. I would hope the new instance would pick up the changed default hci device. I haven't tried that yet, but creating a new instance of Noble might also be the remedy for when Noble seems completely non-functional, until you run a soma probe.

Explicit instantiation should also be the trick to use multiple adapters in parallel. With USB extension cables, you might want to link a SOMA device to a particular adapter, instead of running a separate Homebridge SOMA instance for that device. Or maybe automatically use the adapter with the highest rssi value for the device? I'm getting a bit ahead of myself here.

I'm not sure /etc/defaults/homebridge is re-read when restarting only a child bridge. I might want to use a config.json setting for the hci device, instead.

One thing I do occasionally notice is any external dongle I'm using sometimes (not often) drops and then reattaches under a different hci numbered device, i.e. was hci0 now hci1, and nothing works until I restart homebridge as homebridge-soma keeps saying bluetooth is disabled.

Which technically is correct: the hci0 device is disabled (because is doesn't exist). Not sure if cycling through available adapters is a good idea. Of course, when its just the same adapter getting new hci numbers, that's a different story. I would rather hope there's some magic setting to force an adapter to re-appear under the same device id. I don't know if there's a good way to get available hci devices; running hciconfig -a and parsing its text output seems a bit iffy.

ebaauw commented 3 years ago

Just published v1.0.5 with many reliability improvements.

Re-instantiating Noble doesn't prevent the lock up issue that devices are no longer connectable (sometimes remedied by running soma probe). It did cause other issues, so I'm no longer persueing that. I did refactor BleClient significantly, eliminating the TypeErrors for unknown service or charactertistic, and (hopefully) preventing the lockup (by updating a changed reference to the Peripheral on each advertisements). I also added a restartInterval config.json key to restart Homebridge SOMA automatically, as it still locks up on my Pi Zero 2 W. It seems to run fine for extended period of time on a Pi 4B though. I think the issues on the Zero are related to the limited memory, rather than to the different Bluetooth adapters.

I saw some weird kernel messages running with the UB400 adapter (while the onboard Bluetooth was still enabled). Haven't had the time to analyse - I want to re-install PiOS first, to create a clean environment. Still waiting on the UB4A

washcroft commented 3 years ago

Thanks, I think a bug has creeped in as mine won't start with the new version, haven't had time To debug yet but will raise it as a seep rate issue.

The thing that's interesting is that soma-connect seems to be so stable... yet it's just HAP-NodeJS and Noble, same as we have here. I wonder if they're doing anything special?

ebaauw commented 3 years ago

The thing that's interesting is that soma-connect seems to be so stable... yet it's just HAP-NodeJS and Noble, same as we have here. I wonder if they're doing anything special?

Check on the box itself (for access, see https://support.somasmarthome.com/hc/en-us/articles/360014397380-SOMA-Connect-username-and-password or create a file called ssh in the boot partition to enable ssh access) and notice that the NodeJS program crashes and restarts quite often. Also the Connect doesn’t poll the blinds as it only reports the data from the advertisements (positions and battery level).

washcroft commented 3 years ago

Check on the box itself (for access, see https://support.somasmarthome.com/hc/en-us/articles/360014397380-SOMA-Connect-username-and-password or create a file called ssh in the boot partition to enable ssh access) and notice that the NodeJS program crashes and restarts quite often. Also the Connect doesn’t poll the blinds as it only reports the data from the advertisements (positions and battery level).

Aha I didn't realise they were crashing and restarting too, you're right the implementation of features in HomeKit isn't as extensive as this

ebaauw commented 3 years ago

Now running the lite version of Raspberry Pi OS bullseye on my Pi Zero 2 W. This really reduces the memory pressure; htop now shows 0K Swp usage. The Zero 2 would lockup and become completely unresponsive when Swp reaches 100.0M; doing a couple of npm installs of Homebridge SOMA (and underlying noble) with the graphical environment enabled would get you there.

Bullseye comes with Bluez 5.55 stable:

Linux pi12 5.10.63-v7+ #1459 SMP Wed Oct 6 16:41:10 BST 2021 armv7l

$ sudo apt list bluez
Listing... Done
bluez/stable,now 5.55-3.1+rpt1 armhf [installed]
$

whereas buster includes Bluez 5.50 testing.

Linux pi3 5.10.63-v7l+ #1459 SMP Wed Oct 6 16:41:57 BST 2021 armv7l

$ sudo apt list bluez
Listing... Done
bluez/testing,now 5.50-1.2~deb10u2+rpt1 armhf [installed,automatic]

I hope the stable Bluez version will prove to be a bit more reliable. I have yet to test the UB500 under bullseye.

costispavlou commented 2 years ago

[11/22/2021, 8:21:21 AM] [SOMA] Venetian Tilt: request 3608: connect [11/22/2021, 8:21:21 AM] [SOMA] Venetian Tilt: warning: request 3608: no response in 15s [11/22/2021, 8:21:21 AM] [SOMA] Venetian Tilt: warning: polling: failed at stage 0 [11/22/2021, 8:21:21 AM] [SOMA] Bedroom Shade: polling [11/22/2021, 8:21:36 AM] [SOMA] Bedroom Shade: request 3642: connect [11/22/2021, 8:21:36 AM] [SOMA] Bedroom Shade: warning: request 3642: no response in 15s [11/22/2021, 8:21:36 AM] [SOMA] Bedroom Shade: warning: polling: failed at stage 0 [11/22/2021, 8:21:37 AM] [SOMA] Venetian Blind: polling [11/22/2021, 8:21:52 AM] [SOMA] Venetian Blind: request 3601: connect [11/22/2021, 8:21:52 AM] [SOMA] Venetian Blind: warning: request 3601: no response in 15s [11/22/2021, 8:21:52 AM] [SOMA] Venetian Blind: warning: polling: failed at stage 0 [11/22/2021, 8:21:52 AM] [SOMA] Venetian Tilt: polling [11/22/2021, 8:22:07 AM] [SOMA] Venetian Tilt: request 3609: connect [11/22/2021, 8:22:07 AM] [SOMA] Bedroom Shade: polling [11/22/2021, 8:22:07 AM] [SOMA] Venetian Tilt: warning: request 3609: no response in 15s [11/22/2021, 8:22:07 AM] [SOMA] Venetian Tilt: warning: polling: failed at stage 0 [11/22/2021, 8:22:22 AM] [SOMA] Bedroom Shade: request 3643: connect [11/22/2021, 8:22:22 AM] [SOMA] Bedroom Shade: warning: request 3643: no response in 15s [11/22/2021, 8:22:22 AM] [SOMA] Bedroom Shade: warning: polling: failed at stage 0 [11/22/2021, 8:22:23 AM] [SOMA] Venetian Blind: polling [11/22/2021, 8:22:38 AM] [SOMA] Venetian Blind: request 3602: connect [11/22/2021, 8:22:38 AM] [SOMA] Venetian Blind: warning: request 3602: no response in 15s [11/22/2021, 8:22:38 AM] [SOMA] Venetian Blind: warning: polling: failed at stage 0 [11/22/2021, 8:22:38 AM] [SOMA] Venetian Tilt: polling [11/22/2021, 8:22:53 AM] [SOMA] Venetian Tilt: request 3610: connect [11/22/2021, 8:22:53 AM] [SOMA] Venetian Tilt: warning: request 3610: no response in 15s [11/22/2021, 8:22:53 AM] [SOMA] Venetian Tilt: warning: polling: failed at stage 0 [11/22/2021, 8:22:53 AM] [SOMA] Bedroom Shade: polling [11/22/2021, 8:23:08 AM] [SOMA] Bedroom Shade: request 3644: connect [11/22/2021, 8:23:08 AM] [SOMA] Bedroom Shade: warning: request 3644: no response in 15s [11/22/2021, 8:23:08 AM] [SOMA] Bedroom Shade: warning: polling: failed at stage 0 [11/22/2021, 8:23:09 AM] [SOMA] Venetian Blind: polling

ebaauw commented 2 years ago

@costispavlou that looks like the issue where Noble becomes unresponsive for no apparent reason. As mentioned above, usually this is remedied by running soma probe. If not, restarting Homebridge should help.

costispavlou commented 2 years ago

@ebaauw thanks for the quick reply. This issue is persistent since the day I installed. I restarted 4-5 times yesterday nothing worked. How can I run soma probe?

costispavlou commented 2 years ago

also do you know of a way to autorestart homebridge every X hours as a cheap workaround

costispavlou commented 2 years ago

[11/22/2021, 9:28:57 AM] [SOMA] Venetian Tilt: polling: ok [11/22/2021, 9:28:57 AM] [SOMA] Venetian Tilt: set position from 100 to 2 [11/22/2021, 9:28:57 AM] [SOMA] Venetian Tilt: set Current Position from 0% to 100% [11/22/2021, 9:28:57 AM] [SOMA] Venetian Tilt: set Position State from 1 to 2 [11/22/2021, 9:29:00 AM] [SOMA] Venetian Blind: polling [11/22/2021, 9:29:01 AM] [SOMA] Venetian Blind: set Received Signal Strength Indication from -87 to -73 [11/22/2021, 9:29:01 AM] [SOMA] Venetian Blind: request 41: discoverService shadeService [11/22/2021, 9:29:01 AM] [SOMA] Venetian Blind: warning: request 41: disconnected unexpectedly [11/22/2021, 9:29:01 AM] [SOMA] Venetian Blind: warning: polling: failed at stage 0 [11/22/2021, 9:29:02 AM] [SOMA] Venetian Tilt: set position from 2 to 0 [11/22/2021, 9:29:06 AM] [SOMA] Venetian Blind: polling [11/22/2021, 9:29:07 AM] [SOMA] Venetian Blind: request 43: discoverService shadeService [11/22/2021, 9:29:07 AM] [SOMA] Venetian Blind: warning: request 43: disconnected unexpectedly [11/22/2021, 9:29:07 AM] [SOMA] Venetian Blind: warning: polling: failed at stage 0 [11/22/2021, 9:29:08 AM] [SOMA] Venetian Tilt Battery: set Battery Level from 72% to 70% [11/22/2021, 9:29:12 AM] [SOMA] Venetian Blind: polling [11/22/2021, 9:29:13 AM] [SOMA] Venetian Blind: set Received Signal Strength Indication from -73 to -74 [11/22/2021, 9:29:14 AM] [SOMA] Venetian Blind: set Last Updated from "Mon Nov 22 2021 09:24:00" to "Mon Nov 22 2021 09:29:12" [11/22/2021, 9:29:16 AM] [SOMA] Venetian Blind: polling: ok [11/22/2021, 9:29:16 AM] [SOMA] Bedroom Shade: polling [11/22/2021, 9:29:17 AM] [SOMA] Bedroom Shade: set Received Signal Strength Indication from -96 to -95 [11/22/2021, 9:29:17 AM] [SOMA] Bedroom Shade: request 43: discoverService shadeService [11/22/2021, 9:29:17 AM] [SOMA] Bedroom Shade: warning: request 43: disconnected unexpectedly [11/22/2021, 9:29:17 AM] [SOMA] Bedroom Shade: warning: polling: failed at stage 0 [11/22/2021, 9:29:23 AM] [SOMA] Bedroom Shade: polling [11/22/2021, 9:29:24 AM] [SOMA] Bedroom Shade: set Received Signal Strength Indication from -95 to -93 [11/22/2021, 9:29:26 AM] [SOMA] Bedroom Shade: set Last Updated from "Mon Nov 22 2021 09:24:12" to "Mon Nov 22 2021 09:29:23" [11/22/2021, 9:29:33 AM] [SOMA] Bedroom Shade: polling: ok [11/22/2021, 9:30:07 AM] [SOMA] Venetian Tilt Battery: set Battery Level from 70% to 71% [11/22/2021, 9:31:07 AM] [SOMA] Venetian Tilt Battery: set Battery Level from 71% to 72% [11/22/2021, 9:33:52 AM] [SOMA] Venetian Tilt: polling [11/22/2021, 9:33:52 AM] [SOMA] Venetian Tilt: set Received Signal Strength Indication from -72 to -81 [11/22/2021, 9:33:54 AM] [SOMA] Venetian Tilt: set Last Updated from "Mon Nov 22 2021 09:28:52" to "Mon Nov 22 2021 09:33:52" [11/22/2021, 9:33:57 AM] [SOMA] Venetian Tilt: polling: ok [11/22/2021, 9:34:12 AM] [SOMA] Venetian Blind: polling [11/22/2021, 9:34:13 AM] [SOMA] Venetian Blind: set Received Signal Strength Indication from -74 to -73 [11/22/2021, 9:34:13 AM] [SOMA] Venetian Blind: request 60: discoverService shadeService [11/22/2021, 9:34:13 AM] [SOMA] Venetian Blind: warning: request 60: disconnected unexpectedly [11/22/2021, 9:34:13 AM] [SOMA] Venetian Blind: warning: polling: failed at stage 0 [11/22/2021, 9:34:18 AM] [SOMA] Venetian Blind: polling [11/22/2021, 9:34:19 AM] [SOMA] Venetian Blind: set Received Signal Strength Indication from -73 to -86 [11/22/2021, 9:34:19 AM] [SOMA] Venetian Blind: request 62: discoverService shadeService [11/22/2021, 9:34:19 AM] [SOMA] Venetian Blind: warning: request 62: disconnected unexpectedly [11/22/2021, 9:34:19 AM] [SOMA] Venetian Blind: warning: polling: failed at stage 0 [11/22/2021, 9:34:23 AM] [SOMA] Bedroom Shade: polling [11/22/2021, 9:34:24 AM] [SOMA] warning: heartbeat 933, drift 380 [11/22/2021, 9:34:24 AM] [SOMA] Bedroom Shade: set Received Signal Strength Indication from -93 to -97 [11/22/2021, 9:34:24 AM] [SOMA] Bedroom Shade: request 60: discoverService shadeService [11/22/2021, 9:34:24 AM] [SOMA] Bedroom Shade: warning: request 60: disconnected unexpectedly [11/22/2021, 9:34:24 AM] [SOMA] Bedroom Shade: warning: polling: failed at stage 0 [11/22/2021, 9:34:25 AM] [SOMA] Venetian Blind: polling [11/22/2021, 9:34:26 AM] [SOMA] Venetian Blind: set Received Signal Strength Indication from -86 to -74 [11/22/2021, 9:34:27 AM] [SOMA] Venetian Blind: set Last Updated from "Mon Nov 22 2021 09:29:12" to "Mon Nov 22 2021 09:34:25" [11/22/2021, 9:34:30 AM] [SOMA] Venetian Blind: polling: ok [11/22/2021, 9:34:30 AM] [SOMA] Bedroom Shade: polling [11/22/2021, 9:34:30 AM] [SOMA] warning: heartbeat 939, drift 405 [11/22/2021, 9:34:30 AM] [SOMA] Bedroom Shade: set Received Signal Strength Indication from -97 to -94 [11/22/2021, 9:34:33 AM] [SOMA] Bedroom Shade: set Last Updated from "Mon Nov 22 2021 09:29:23" to "Mon Nov 22 2021 09:34:30" [11/22/2021, 9:34:38 AM] [SOMA] Bedroom Shade: polling: ok [11/22/2021, 9:38:52 AM] [SOMA] Venetian Tilt: polling [11/22/2021, 9:38:54 AM] [SOMA] Venetian Tilt: set Last Updated from "Mon Nov 22 2021 09:33:52" to "Mon Nov 22 2021 09:38:52" [11/22/2021, 9:38:57 AM] [SOMA] Venetian Tilt: polling: ok [11/22/2021, 9:39:25 AM] [SOMA] Venetian Blind: polling [11/22/2021, 9:39:26 AM] [SOMA] Venetian Blind: set Received Signal Strength Indication from -74 to -86 [11/22/2021, 9:39:26 AM] [SOMA] Venetian Blind: request 79: discoverService shadeService [11/22/2021, 9:39:26 AM] [SOMA] Venetian Blind: warning: request 79: disconnected unexpectedly [11/22/2021, 9:39:26 AM] [SOMA] Venetian Blind: warning: polling: failed at stage 0 [11/22/2021, 9:39:26 AM] [SOMA] Bedroom Shade: polling [11/22/2021, 9:39:26 AM] [SOMA] warning: heartbeat 1235, drift 352 [11/22/2021, 9:39:26 AM] [SOMA] Bedroom Shade: set Received Signal Strength Indication from -94 to -95 [11/22/2021, 9:39:26 AM] [SOMA] Bedroom Shade: request 77: discoverService shadeService [11/22/2021, 9:39:26 AM] [SOMA] Bedroom Shade: warning: request 77: disconnected unexpectedly [11/22/2021, 9:39:26 AM] [SOMA] Bedroom Shade: warning: polling: failed at stage 0 [11/22/2021, 9:39:31 AM] [SOMA] Venetian Blind: polling [11/22/2021, 9:39:33 AM] [SOMA] Venetian Blind: set Last Updated from "Mon Nov 22 2021 09:34:25" to "Mon Nov 22 2021 09:39:31" [11/22/2021, 9:39:35 AM] [SOMA] Venetian Blind: polling: ok [11/22/2021, 9:39:35 AM] [SOMA] Bedroom Shade: polling [11/22/2021, 9:39:37 AM] [SOMA] warning: heartbeat 1245, drift 753 [11/22/2021, 9:39:37 AM] [SOMA] Bedroom Shade: set Received Signal Strength Indication from -95 to -97 [11/22/2021, 9:39:39 AM] [SOMA] Bedroom Shade: set Last Updated from "Mon Nov 22 2021 09:34:30" to "Mon Nov 22 2021 09:39:35" [11/22/2021, 9:39:45 AM] [SOMA] Bedroom Shade: polling: ok [11/22/2021, 9:43:52 AM] [SOMA] Venetian Tilt: polling [11/22/2021, 9:43:52 AM] [SOMA] Venetian Tilt: set Received Signal Strength Indication from -81 to -73 [11/22/2021, 9:43:54 AM] [SOMA] Venetian Tilt: set Last Updated from "Mon Nov 22 2021 09:38:52" to "Mon Nov 22 2021 09:43:52" [11/22/2021, 9:43:57 AM] [SOMA] Venetian Tilt: polling: ok [11/22/2021, 9:44:31 AM] [SOMA] Venetian Blind: polling [11/22/2021, 9:44:31 AM] [SOMA] Venetian Blind: set Received Signal Strength Indication from -86 to -73 [11/22/2021, 9:44:32 AM] [SOMA] Venetian Blind: set Last Updated from "Mon Nov 22 2021 09:39:31" to "Mon Nov 22 2021 09:44:31" [11/22/2021, 9:44:35 AM] [SOMA] Venetian Blind: polling: ok [11/22/2021, 9:44:35 AM] [SOMA] Bedroom Shade: polling [11/22/2021, 9:44:36 AM] [SOMA] Bedroom Shade: set Received Signal Strength Indication from -97 to -95 [11/22/2021, 9:44:36 AM] [SOMA] Bedroom Shade: request 94: discoverService shadeService [11/22/2021, 9:44:36 AM] [SOMA] Bedroom Shade: warning: request 94: disconnected unexpectedly [11/22/2021, 9:44:36 AM] [SOMA] Bedroom Shade: warning: polling: failed at stage 0

ebaauw commented 2 years ago

[11/22/2021, 9:44:35 AM] [SOMA] Venetian Blind: polling: ok

If you're still seeing "polling: ok" messages. Noble hasn't locked up.

[11/22/2021, 8:23:08 AM] [SOMA] Bedroom Shade: request 3644: connect [11/22/2021, 8:23:08 AM] [SOMA] Bedroom Shade: warning: request 3644: no response in 15s ... [11/22/2021, 9:39:26 AM] [SOMA] Bedroom Shade: request 77: discoverService shadeService [11/22/2021, 9:39:26 AM] [SOMA] Bedroom Shade: warning: request 77: disconnected unexpectedly

These are just typical cases of "shit happens". Homebridge SOMA will retry automatically if this happens during polling, but fails if this happens when changing the shade state from HomeKit. I still need to refactor that logic to make it a bit more resilient.

[11/22/2021, 9:44:36 AM] [SOMA] Bedroom Shade: set Received Signal Strength Indication from -97 to -95

In my experience, RSSI values below -80 are challenging for a stable connection. Try moving the BLE antenna closer to the shades.

also do you know of a way to autorestart homebridge every X hours as a cheap workaround

Set restartInterval in config.json, see https://github.com/ebaauw/homebridge-soma/releases/tag/v1.0.6.

How can I run soma probe?

From the command line (e.g. through the Terminal feature in the Homebridge UI).

costispavlou commented 2 years ago

log file is full of soma reports so yeah.. noble hasn't locked. Rpi is 3m away from 2 blinds (venetian blind and tilt) and 8-10m from bedroom.

ebaauw commented 2 years ago

8-10m might be pushing it, especially if there's walls and/or ceilings in between. Using a metal case for the Raspberry Pi might also deteriorate the Bluetooth connection, as would interference on the 2.4 GHz band (caused by USB-3 (!), WiFi, DECT, or even microwave ovens). In that scenario, you might try a BLE dongle with a USB extension cable, see above.

Worst case, you might need a separate Raspberry Pi for the bedroom, see also #4.

ebaauw commented 2 years ago

Worst case, you might need a separate Raspberry Pi for the bedroom, see also #4.

I'd suggest a Pi Zero 2 W for that - it seems to run OK in my testing, after increasing the swap space (still need to do a write-up on that).

costispavlou commented 2 years ago

I don't really care about the bedroom blind, I can open it via the app. The issue occurs to the ones that are 2,5m away Am I wrong?

costispavlou commented 2 years ago

I've added a restart to be executed every 2 hours. Log file is full of soma entries. I also couldnt manage to run the probe command

ebaauw commented 2 years ago

You need to specify which device to probe, eg soma -D probe "Bedroom Shade". The error message seems to be copied from my Homebridge SC plugin (for the SOMA Connect).

ebaauw commented 2 years ago

Lastest beta, v1.0.8-0 fixes soma message and implements info, close, open, stop, and position commands to control the SOMA devices from the command line. Homebridge SOMA, ble and soma now log in detail the hardware and OS in debug mode.

costispavlou commented 2 years ago

@ebaauw thank you, I've run all commands as you instructed but the log is again filled of soma entries.

gonna restart and see if this persists. I will also try the beta and report back.

ebaauw commented 2 years ago

The log entries are normal. It's just Homebridge SOMA informing you what it's doing. Set Log Level to 0 on each Window Covering service in Eve to suppress them.

The warnings are, as I mentioned above ("shit happens") unavoidable, I'm afraid. You cannot suppress them. If they happen during polling, Homebridge SOMA should recover (and does, in your case, as indicated by the "polling: ok" messages). If they happen when changing the state from HomeKit, the change fails, the HomeKit state reverts, and you need to retry manually. As I indicated above, I still need to refactor that logic to re-try automatically.

costispavlou commented 2 years ago

alright thanks. Since the entries/warnings mean nothing to me, nor have any use, I will try what you mentioned. should I install the beta or you wouldn't recommend ?

costispavlou commented 2 years ago

Set Log Level to 0 on each Window Covering service in Eve to suppress them.

can you be a bit more specific ? I don't have eve.

ebaauw commented 2 years ago

It’s a custom characteristic so you can dynamically set the log level per accessory. You need a decent HomeKit app for that, as Home doesn’t support custom characetristics.

You won’t be able to use the full features of Homebridge SOMA, when using only Home.

The beta doesn’t yet contain the refactored logic, so I don’t expect it to behave differently. I need to cut a new version for testing it myself, making sure I didn’t screw up anything making the changes for logging the hardware and OS details. Also, I’ll be needing the new soma commands to develop and test the refactored logic.

costispavlou commented 2 years ago

got you. I'm sorry to've waste your time then. Hopefully you'll find a way to make it work as it should. Let me know if you need any beta testers.

ebaauw commented 2 years ago

Hopefully you'll find a way to make it work as it should.

That’s part of the challenge: I am new to BLE and still figuring out how it should (is supposed to) work. The SOMA devices are great and they’ve been of great help providing me with all technical details. However, the NodeJS / Noble part is really challenging.

costispavlou commented 2 years ago

Nuh SOMA devices suck big time. They have a bunch of negatives. Good as an idea, but crappy to say the least implementation. -no physical controls -crappy ui -incompatible with everything unless you are a developer + -bad battery life not to mention their price. Good for a $10-20 device, other than that one of the worst purchases of my life.

ebaauw commented 2 years ago

Beta v1.0.10-0 now automatically retries each read or write request up to five times. That should address the majority of cases where the blinds don't react to changes from HomeKit. I might still need to synchronise changes from HomeKit and polling (making sure only a single request happens concurrently), but I want to see how this change works out first.

Also fixed an uncaught TypeError that caused Homebridge to crash.

Added Position Change characteristic to step the position up or down, similar to Brightness Change in Homebridge Hue or Volume Change in Homebridge ZP. Intended usage is manual control by a stateless programmable switch. Added corresponding stepUp and stepDown commands to soma. Also added up and down. For Smart Blind devices, they're similar to open and close, but for Tilt devices they're similar to close up and close down.

ebaauw / homebridge-soma

SOMA Blind fails to open/close #6