Socat open a port, zigbee addon cannot "open" it?

Setup, Configuration and Use Beginners
, ,
1
  • Platform information:
  • Hardware: Rpi4, 2GB
  • OS: Linux openhabian 6.6.20+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.20-1+rpt1 (2024-03-07) aarch64
    • Java Runtime Environment: standard installation
    • openHAB version: OH4 (new installation + restored backup)

Hi,

I have an issue with my zigbee configuration I cannot figure out alone. I use an external, rooted Silvercrest) Zigbee hub and the socat utility to create a local serial port for OH, as described here.

Everything worked till last week, when suddently I have got a “Communication Error”, here below the log (zigbee debug enabled)

==> /var/log/openhab/events.log <==
2024-04-03 20:29:57.231 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_ember:d262c81014' changed from UNINITIALIZED (DISABLED) to INITIALIZING
2024-04-03 20:29:57.270 [INFO ] [penhab.event.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:coordinator_ember:d262c81014 changed to UNKNOWN.
==> /var/log/openhab/openhab.log <==
2024-04-03 20:29:58.266 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2024-04-03 20:29:58.267 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2024-04-03 20:29:58.270 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
2024-04-03 20:29:58.307 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C138A93227C615: ZigBee reading network state complete.
2024-04-03 20:29:58.354 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C1382CA259B890: ZigBee reading network state complete.
2024-04-03 20:29:58.391 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B000EF3CD0B: ZigBee reading network state complete.
2024-04-03 20:29:58.417 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 60A423FFFE0EA5BF: ZigBee reading network state complete.
2024-04-03 20:29:58.476 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - BC33ACFFFE47E968: ZigBee reading network state complete.
2024-04-03 20:29:58.519 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C138FF42C3943B: ZigBee reading network state complete.
2024-04-03 20:29:58.559 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 000D6FFFFE816CEF: ZigBee reading network state complete.
2024-04-03 20:29:58.599 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C138F29CEE0A1A: ZigBee reading network state complete.
2024-04-03 20:29:58.645 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C1387803356E06: ZigBee reading network state complete.
2024-04-03 20:29:58.687 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C1385EDBF00B8E: ZigBee reading network state complete.
2024-04-03 20:29:58.732 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C138AB208EFD4A: ZigBee reading network state complete.
2024-04-03 20:29:58.782 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C138CEFD09C413: ZigBee reading network state complete.
2024-04-03 20:29:58.826 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C13826147B4BC4: ZigBee reading network state complete.
2024-04-03 20:29:58.869 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C13875162B4AEF: ZigBee reading network state complete.
2024-04-03 20:29:58.911 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C13899F0DE2DFA: ZigBee reading network state complete.
2024-04-03 20:29:58.948 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 000D6FFFFE816D5B: ZigBee reading network state complete.
2024-04-03 20:29:58.993 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C1389699F6EDE3: ZigBee reading network state complete.
2024-04-03 20:29:59.033 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - A4C1380C5680A5A6: ZigBee reading network state complete.
2024-04-03 20:29:59.036 [DEBUG] [nding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyzbbridge1] at 115200 baud, flow control FLOWCONTROL_OUT_RTSCTS.
2024-04-03 20:29:59.042 [DEBUG] [nding.zigbee.serial.ZigBeeSerialPort] - No communication ports found, cannot connect to [/dev/ttyzbbridge1]
2024-04-03 20:29:59.043 [ERROR] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Unable to open serial port

This is the socat log file (max debug)

2024/04/03 20:04:10 socat[48217] I socat by Gerhard Rieger and contributors - see www.dest-unreach.org
2024/04/03 20:04:10 socat[48217] I This product includes software developed by the OpenSSL Project for use in the OpenSSL Toolkit. (http://www.openssl.org/)
2024/04/03 20:04:10 socat[48217] I This product includes software written by Tim Hudson (tjh@cryptsoft.com)
2024/04/03 20:04:10 socat[48217] I setting option "symbolic-link" to "/dev/ttyzbbridge1"
2024/04/03 20:04:10 socat[48217] I setting option "raw"
2024/04/03 20:04:10 socat[48217] I setting option "user" to 106
2024/04/03 20:04:10 socat[48217] I setting option "group" to 20
2024/04/03 20:04:10 socat[48217] I setting option "perm" to 511
2024/04/03 20:04:10 socat[48217] I openpty({6}, {7}, {"/dev/pts/3"},,) -> 0
2024/04/03 20:04:10 socat[48217] N PTY is /dev/pts/3
2024/04/03 20:04:10 socat[48217] N opening connection to AF=2 192.168.178.123:8888
2024/04/03 20:04:10 socat[48217] I starting connect loop
2024/04/03 20:04:10 socat[48217] I socket(2, 1, 6) -> 8
2024/04/03 20:04:10 socat[48217] N successfully connected from local address AF=2 192.168.178.88:60696
2024/04/03 20:04:10 socat[48217] I resolved and opened all sock addresses
2024/04/03 20:04:10 socat[48217] N starting data transfer loop with FDs [6,6] and [8,8]

and the related files

openhabian@openhabian:~ $ ls -l /dev/ttyzbbridge1  /dev/pts/3
crwxrwxrwx 1 openhab dialout 136, 3 Apr  3 20:04 /dev/pts/3
lrwxrwxrwx 1 root    root        10 Apr  3 20:04 /dev/ttyzbbridge1 -> /dev/pts/3

I do not see anything wrong, so should I continue to debug to find the issue?

Thanks
Max

2

Hi all

I have tried now to use a zigbee sniffer (link) to check if a different program might be able to talk to the zigbee coordinator.

And indeed…

$ java -jar com.zsmartsystems.zigbee.sniffer-1.0.1.jar -port /dev/ttyzbbridge1 -baud 115200 -flow hardware
Z-Smart Systems Ember Packet Sniffer
NCP initialisation starting...
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
Opened serial port /dev/ttyzbbridge1 at 115200
Ember NCP version     : 6.7.8.0
Ember NCP EUI         : 60A423FFFE0EA5BF
WiresharkZepFrame [sequence=00000000, lqi=144, rssi=-64, data={63 88 8E 62 60 43 C5 F1 6F 04 EB 22}]
WiresharkZepFrame [sequence=00000001, lqi=208, rssi=-48, data={02 00 8E CE D8}]
WiresharkZepFrame [sequence=00000002, lqi=144, rssi=-64, data={63 88 F6 62 60 01 96 21 DB 04 5E 72}]
WiresharkZepFrame [sequence=00000003, lqi=152, rssi=-62, data={63 88 85 62 60 43 C5 10 4F 04 C9 F5}]
WiresharkZepFrame [sequence=00000004, lqi=208, rssi=-48, data={02 00 85 1D 66}]
NCP initialisation complete...
Wireshark destination : /127.0.0.1:17754
Logging on channel    : 11
No device ID set. Last 16 bits of device EUID will be used.
WiresharkZepFrame [sequence=00000005, lqi=160, rssi=-60, data={63 88 5D 62 60 60 3A A5 7F 04 CC 90}]
WiresharkZepFrame [sequence=00000006, lqi=236, rssi=-41, data={02 00 5D D8 3C}]
WiresharkZepFrame [sequence=00000007, lqi=224, rssi=-44, data={63 88 1A 62 60 60 3A 0D E9 04 AB ED}]
WiresharkZepFrame [sequence=00000008, lqi=236, rssi=-41, data={02 00 1A 63 0A}]
WiresharkZepFrame [sequence=00000009, lqi=84, rssi=-79, data={63 88 FB 62 60 01 96 9F F3 04 29 BF}]
WiresharkZepFrame [sequence=0000000A, lqi=156, rssi=-61, data={63 88 B4 62 60 60 3A C9 3D 04 14 F1}]
WiresharkZepFrame [sequence=0000000B, lqi=236, rssi=-41, data={02 00 B4 17 46}]

... many more lines follow

From the output I could infer

  • The coordinator is responding (NCP version is correct)
  • The zigbee network is working (packets are shown)

Does anybody agree?

If yes, why is Openhab not able to open the very same port? I have read in another post (sorry, I cannot find the link anymore) that in a similar case there was an issue with /var/lock access rights. In my case

$ ls /var/lock/ -l
total 12
-rw-r--r-- 1 root    root    22 Apr 12 23:07 asound.state.lock
-rw-r--r-- 1 root    root    22 Apr 12 23:07 card0.lock
-rw-r--r-- 1 openhab openhab 11 Apr 12 23:09 LCK..ttyAMA0
drwxr-xr-x 2 root    root    40 Apr 12 23:06 subsys

meaning that at least the z-wave addon is able to create a lock file here.

Anything obvious am I missing?

Thanks
Max