MAX - CUL - receives but doesn't send

PaulL · September 30, 2020, 9:36am

I have an OpenHab installation, and I’ve been using OpenHab 1 on two spare Raspberry Pis to connect to my Max devices - OpenHab 2 is less happy connecting to Max.

I’m worried about longevity of Openhab 1, so wanted to move to Homegear on the subsidiary Pis instead (still Openhab on the boiler controller).

My install went very easily, and initially it paired and recognised all my devices. But it then mysteriously stopped working. I reverted all my devices to being paired with Openhab 1 as I needed to go to work first part of the week. I’m back home, and working on Homegear again. I’m now at a stage where I’m working on a single Pi, and trying to pair the valves and thermostats to it again.

What I get is a pairing message coming in from the thermostat, and my Homegear appears to try to respond. But the Max devices simply don’t see the response.

Trouble shooting I’ve done is:

Swapped the CUL devices between my Pis. Still no change
Switched back to Openhab 1 on same Pi with same device. Pairing within 2 seconds (therefore, not a hardware problem)
Looked at permissions on the /dev/ttyACM0 - it is set to rw for homegear

crw-rw---- 1 homegear homegear 166, 0 Sep 30 22:17 /dev/ttyACM0

(not sure why the user is homegear, for a while it was root dialout, but homegear is in that group anyway)
Reinstalled homegear

It’s still behaving the same. And I really don’t understand why it worked for a while then stopped working.

My next step is to reinstall the full raspberrypi, then homegear, but before I do that I was wondering if anyone has any ideas? I struggle that it’s reading from the port fine, but not writing to it, and yet openhab can write to it fine. I’m assuming it’s failing to write to the port because it says it’s writing, but the devices just ignore it and keep sending a pairing request. It seems like it should be a permissions issue - that it can read and not write - but surely it’d give a permissions error if that was the case? I’ve tried setting permissions to 777 just in case:

root@raspberrypi:/home/pi# chmod 777 /dev/ttyACM0
root@raspberrypi:/home/pi# ls -l /dev/ttyACM0
crwxrwxrwx 1 homegear homegear 166, 0 Sep 30 22:34 /dev/ttyACM0

But no difference.

Logs of what’s going on:

09/30/20 22:30:15.303 MAX packet received (KITCHEN-MAX-CUL, RSSI: 0x3E): 17000400136742000000001003FF4D455130383535303635
09/30/20 22:30:15.412 Module MAX: CUL "KITCHEN-MAX-CUL": Info: Sending (KITCHEN-MAX-CUL, WOR: yes): 0BC50001FD0AA021367420000
09/30/20 22:30:18.496 Module MAX: CUL "KITCHEN-MAX-CUL": Info: Sending (KITCHEN-MAX-CUL, WOR: yes): 0BC50001FD0AA021367420000
09/30/20 22:30:20.275 MAX packet received (KITCHEN-MAX-CUL, RSSI: 0x3E): 17000400136742000000001003FF4D455130383535303635
09/30/20 22:30:20.598 Module MAX: CUL "KITCHEN-MAX-CUL": Info: Sending (KITCHEN-MAX-CUL, WOR: yes): 0BC70001FD0AA021367420000
09/30/20 22:30:23.691 Module MAX: CUL "KITCHEN-MAX-CUL": Info: Sending (KITCHEN-MAX-CUL, WOR: yes): 0BC70001FD0AA021367420000
09/30/20 22:30:25.275 MAX packet received (KITCHEN-MAX-CUL, RSSI: 0x3E): 17000400136742000000001003FF4D455130383535303635
09/30/20 22:30:25.492 Module MAX: CUL "KITCHEN-MAX-CUL": Info: Sending (KITCHEN-MAX-CUL, WOR: yes): 0BC90001FD0AA021367420000
09/30/20 22:30:28.586 Module MAX: CUL "KITCHEN-MAX-CUL": Info: Sending (KITCHEN-MAX-CUL, WOR: yes): 0BC90001FD0AA021367420000
09/30/20 22:30:30.011 RPC Server (Port 2001): Info: Client number 11 is calling RPC method: ping (2) Parameters:
(String) F80C2E2A-2795-DA83-F307-9A029251254E
09/30/20 22:30:30.019 RPC Server (Port 2001): Info: Client number 11 is calling RPC method: listBidcosInterfaces (2) Parameters:
09/30/20 22:30:30.275 MAX packet received (KITCHEN-MAX-CUL, RSSI: 0x3E): 17000400136742000000001003FF4D455130383535303635
09/30/20 22:30:30.387 Module MAX: CUL "KITCHEN-MAX-CUL": Info: Sending (KITCHEN-MAX-CUL, WOR: yes): 0BCB0001FD0AA021367420000
09/30/20 22:30:33.480 Module MAX: CUL "KITCHEN-MAX-CUL": Info: Sending (KITCHEN-MAX-CUL, WOR: yes): 0BCB0001FD0AA021367420000
09/30/20 22:30:35.275 MAX packet received (KITCHEN-MAX-CUL, RSSI: 0x3E): 17000400136742000000001003FF4D455130383535303635
09/30/20 22:30:35.581 Module MAX: CUL "KITCHEN-MAX-CUL": Info: Sending (KITCHEN-MAX-CUL, WOR: yes): 0BCD0001FD0AA021367420000
09/30/20 22:30:35.584 Module MAX: CUL "KITCHEN-MAX-CUL": Warning: CUL with id KITCHEN-MAX-CUL reached 1% limit. You need to wait, before sending is allowed again.

pmayer · September 30, 2020, 9:57am

Hey Paul,

looks ok to me. Could you post the section of the log from the homegear startup?

Also show your max.conf and tell us which version of homegear you are using: dpkg -l | grep homegear.

For further Debugging you can change the debuglevel to 5 or higher and have a look at the logs then.
Either in the main.conf or at runtime via the homegear console:

sudo homegear -r
dl 5

Cheers,
Patrik

PaulL · September 30, 2020, 10:07am

Thanks for the quick reply Patrik.

Homegear version:

root@raspberrypi:/home/pi# dpkg -l |grep homegear
ii  homegear                       0.8.0-3085                          armhf        Interface program to your smart home devices
ii  homegear-adminui               0.1.0-253                           all          Provides an administrative user interface for Homegear.
ii  homegear-management            0.8.0-3085                          armhf        Management service for Homegear
ii  homegear-max                   0.8.0-3085                          armhf        HomeMatic BidCoS module for Homegear
ii  homegear-nodes-core            0.8.0-3085                          armhf        Core nodes for Homegear's Node-BLUE
ii  homegear-ui                    0.1.0-350                           all          Provides an user interface for Homegear.
ii  libhomegear-base               0.8.0-3085                          armhf        Base library for Homegear
ii  libhomegear-ipc                0.1.2-41                            armhf        IPC library for Homegear
ii  libhomegear-node               0.1.7-52                            armhf        Node library for Homegear
ii  python3-homegear               1.0.14-1                            armhf        Python module for Homegear

Max.conf


---------------------------------- MAX!  ----------------------------------
___________________________________________________________________________

#######################################
########## General Settings  ##########
#######################################

[General]

moduleEnabled = true

## The MAX! address of Homegear. It is recommended to change this to a random 3 byte hexadecimal
## value starting with 0xFD (e. g. 0xFD43AB). Only change this, when no MAX! devices
## are paired to Homegear as existing pairings will not work anymore!
centralAddress = 0xFD0AA02

#######################################
################# CUL #################
#######################################

## The device family this interface is for
[CUL]

## Specify an unique id here to identify this device in Homegear
id = KITCHEN-MAX-CUL

## When default is set to "true" Homegear will assign this device
## to new peers.
default = true

## Options: cul, coc, cc1100
deviceType = cul

device = /dev/ttyACM0

## Should be "40" for MAX!
responseDelay = 95

Note i have tried both 40 and 95 for the responseDelay, as I saw some suggestion that 95 was the right value, but that might have been for a CUN.

Homegear startup:

09/30/20 22:17:21.916 Starting Homegear...
09/30/20 22:17:21.918 Homegear version: 0.8.0-3085
09/30/20 22:17:21.918 Determining maximum thread count...
09/30/20 22:17:23.101 Maximum thread count is: 438
09/30/20 22:17:23.178 Info: Backing up database...
09/30/20 22:17:25.506 Initializing database...
09/30/20 22:17:36.458 Homegear instance ID: 0005B0419662D1A5-AEE7B9CF-67F4-F452-D59E-977DD4BB1214
09/30/20 22:17:36.470 Debug: Loading licensing modules
09/30/20 22:17:36.471 Initializing system variable controller...
09/30/20 22:17:36.482 Debug: Loading family modules
09/30/20 22:17:36.482 Info: Loading family module (type 1) mod_miscellaneous.so
09/30/20 22:17:36.501 Info: Loading settings from /etc/homegear/families/miscellaneous.conf
09/30/20 22:17:36.508 Error: Physical interface with title "general" has no type or id set. Please control your settings in "/etc/homegear/families/miscellaneous.conf".
09/30/20 22:17:36.511 Info: Loading family module (type 1) mod_max.so
09/30/20 22:17:36.549 Info: Loading settings from /etc/homegear/families/max.conf
09/30/20 22:17:36.550 Error: Physical interface with title "general" has no type or id set. Please control your settings in "/etc/homegear/families/max.conf".
09/30/20 22:17:36.559 Info: Setting up physical interfaces and GPIOs...
09/30/20 22:17:36.568 Info: Dropping privileges to user homegear (112) and group homegear (117)
09/30/20 22:17:36.577 Info: Homegear is (now) running as user with id 112 and group with id 117.
09/30/20 22:17:36.708 Starting script engine server...
09/30/20 22:17:36.770 Initializing licensing controller...
09/30/20 22:17:36.770 Loading licensing controller data...
09/30/20 22:17:36.770 Loading devices...
09/30/20 22:17:36.770 Loading XML RPC devices...
09/30/20 22:17:36.909 Loading device 1
09/30/20 22:17:36.916 Module MAX: Info: Central address set to 0xFD0AA02.
09/30/20 22:17:36.916 Loading XML RPC devices...
09/30/20 22:17:36.924 Warning: variables with id "custom_ch7_values" does not exist.
09/30/20 22:17:36.930 Warning: variables with id "custom_ch7_values" does not exist.
09/30/20 22:17:36.933 Warning: script2 in "runProgram" does not contain CDATA.
09/30/20 22:17:36.938 Warning: configParameters with id "config" does not exist.
09/30/20 22:17:36.939 Warning: configParameters with id "config" does not exist.
09/30/20 22:17:36.944 Loading device 2
09/30/20 22:17:36.946 Initializing RPC client...
09/30/20 22:17:36.946 Starting XML RPC server RPCServer1 listening on :::2001...
09/30/20 22:17:36.986 RPC Server (Port 2001): Warning: SSL is not enabled for this RPC server. It is strongly recommended to disable all unencrypted RPC servers when the connected clients support it.
09/30/20 22:17:36.986 RPC Server (Port 2001): Warning: RPC server has no authorization enabled. Everybody on your local network can login into this installation. It is strongly recommended to enable authorization on all RPC servers when the connected clients support it.
09/30/20 22:17:36.986 RPC Server (Port 2001): Info: Enabling no authentication.
09/30/20 22:17:36.986 RPC Server (Port 2001): Info: Enabling session authentication for WebSockets.
09/30/20 22:17:36.987 Starting XML RPC server RPCServer2 listening on :::2002, SSL enabled...
09/30/20 22:17:36.987 RPC Server (Port 2001): Info: RPC Server started listening on address :: and port 2001
09/30/20 22:17:37.026 RPC Server (Port 2002): Warning: RPC server has no authorization enabled. Everybody on your local network can login into this installation. It is strongly recommended to enable authorization on all RPC servers when the connected clients support it.
09/30/20 22:17:37.027 RPC Server (Port 2002): Info: Enabling no authentication.
09/30/20 22:17:37.027 RPC Server (Port 2002): Info: Enabling session authentication for WebSockets.
09/30/20 22:17:37.090 Starting XML RPC server RPCServer3 listening on :::2003, SSL enabled, authentication enabled...
09/30/20 22:17:37.090 RPC Server (Port 2002): Info: RPC Server started listening on address :: and port 2002
09/30/20 22:17:37.129 RPC Server (Port 2003): Info: Enabling basic authentication.
09/30/20 22:17:37.129 RPC Server (Port 2003): Info: Enabling client certificate authentication.
09/30/20 22:17:37.129 RPC Server (Port 2003): Info: Enabling session authentication for WebSockets.
09/30/20 22:17:37.162 Starting XML RPC server RPCServer4 listening on ::1:2004...
09/30/20 22:17:37.201 RPC Server (Port 2004): Info: Enabling no authentication.
09/30/20 22:17:37.201 RPC Server (Port 2004): Info: Enabling session authentication for WebSockets.
09/30/20 22:17:37.202 RPC Server (Port 2004): Info: RPC Server started listening on address ::1 and port 2004
09/30/20 22:17:37.203 Initializing event handler...
09/30/20 22:17:37.203 Loading events...
09/30/20 22:17:37.203 Start listening for packets...
09/30/20 22:17:39.607 Starting IPC server...
09/30/20 22:17:39.617 Starting Node-BLUE server...
09/30/20 22:17:39.717 Starting variable profile manager...
09/30/20 22:17:39.718 Startup complete. Waiting for physical interfaces to connect.
09/30/20 22:17:39.718 Info: Waiting for physical interfaces to connect (0 of 180s).
09/30/20 22:17:39.718 All physical interfaces are connected now.
09/30/20 22:17:39.718 Starting UPnP server...
09/30/20 22:17:43.958 RPC Server (Port 2001): Info: Connection from ::ffff:192.168.1.15:56608 accepted. Client number: 7
09/30/20 22:17:43.962 RPC Server (Port 2001): Info: RPC server client id for client number 7 is: 0
09/30/20 22:17:43.964 RPC Server (Port 2001): Info: Client number 7 is calling RPC method: ping (2) Parameters:
(String) F80C2E2A-2795-DA83-F307-9A029251254E
09/30/20 22:17:43.972 RPC Server (Port 2001): Info: Client number 7 is calling RPC method: listBidcosInterfaces (2) Parameters:
09/30/20 22:17:44.719 UPnP Server: Info: UPnP server: Binding to address: 192.168.1.14
09/30/20 22:17:45.524 IPC Server: Info: Connection accepted. Client number: 0, file descriptor ID: 9
09/30/20 22:17:45.526 IPC Server: Info: Client 0 successfully registered RPC method "managementGetCommandStatus" (this method is registered by 1 client(s)).
09/30/20 22:17:45.527 IPC Server: Info: Client 0 successfully registered RPC method "managementSleep" (this method is registered by 1 client(s)).
09/30/20 22:17:45.528 IPC Server: Info: Client 0 successfully registered RPC method "managementDpkgPackageInstalled" (this method is registered by 1 client(s)).
09/30/20 22:17:45.529 IPC Server: Info: Client 0 successfully registered RPC method "managementGetSystemInfo" (this method is registered by 1 client(s)).
09/30/20 22:17:45.530 IPC Server: Info: Client 0 successfully registered RPC method "managementGetConfigurationEntry" (this method is registered by 1 client(s)).
09/30/20 22:17:45.532 IPC Server: Info: Client 0 successfully registered RPC method "managementServiceCommand" (this method is registered by 1 client(s)).
09/30/20 22:17:45.533 IPC Server: Info: Client 0 successfully registered RPC method "managementReboot" (this method is registered by 1 client(s)).
09/30/20 22:17:45.534 IPC Server: Info: Client 0 successfully registered RPC method "managementShutdown" (this method is registered by 1 client(s)).
09/30/20 22:17:45.535 IPC Server: Info: Client 0 successfully registered RPC method "managementSetConfigurationEntry" (this method is registered by 1 client(s)).
09/30/20 22:17:45.537 IPC Server: Info: Client 0 successfully registered RPC method "managementWriteCloudMaticConfig" (this method is registered by 1 client(s)).
09/30/20 22:17:45.538 IPC Server: Info: Client 0 successfully registered RPC method "managementSetUserPassword" (this method is registered by 1 client(s)).
09/30/20 22:17:45.539 IPC Server: Info: Client 0 successfully registered RPC method "managementInstallNode" (this method is registered by 1 client(s)).
09/30/20 22:17:45.540 IPC Server: Info: Client 0 successfully registered RPC method "managementUninstallNode" (this method is registered by 1 client(s)).
09/30/20 22:17:45.541 IPC Server: Info: Client 0 successfully registered RPC method "managementGetNodePackages" (this method is registered by 1 client(s)).
09/30/20 22:17:45.542 IPC Server: Info: Client 0 successfully registered RPC method "managementAptRunning" (this method is registered by 1 client(s)).
09/30/20 22:17:45.543 IPC Server: Info: Client 0 successfully registered RPC method "managementAptUpdate" (this method is registered by 1 client(s)).
09/30/20 22:17:45.543 IPC Server: Info: Client 0 successfully registered RPC method "managementAptUpgrade" (this method is registered by 1 client(s)).
09/30/20 22:17:45.544 IPC Server: Info: Client 0 successfully registered RPC method "managementAptUpgradeSpecific" (this method is registered by 1 client(s)).
09/30/20 22:17:45.545 IPC Server: Info: Client 0 successfully registered RPC method "managementAptFullUpgrade" (this method is registered by 1 client(s)).
09/30/20 22:17:45.545 IPC Server: Info: Client 0 successfully registered RPC method "managementHomegearUpdateAvailable" (this method is registered by 1 client(s)).
09/30/20 22:17:45.546 IPC Server: Info: Client 0 successfully registered RPC method "managementSystemUpdateAvailable" (this method is registered by 1 client(s)).
09/30/20 22:17:45.547 IPC Server: Info: Client 0 successfully registered RPC method "managementAptInstall" (this method is registered by 1 client(s)).
09/30/20 22:17:45.548 IPC Server: Info: Client 0 successfully registered RPC method "managementAptRemove" (this method is registered by 1 client(s)).
09/30/20 22:17:45.549 IPC Server: Info: Client 0 successfully registered RPC method "managementCreateBackup" (this method is registered by 1 client(s)).
09/30/20 22:17:45.550 IPC Server: Info: Client 0 successfully registered RPC method "managementRestoreBackup" (this method is registered by 1 client(s)).
09/30/20 22:17:45.551 IPC Server: Info: Client 0 successfully registered RPC method "managementSystemReset" (this method is registered by 1 client(s)).
09/30/20 22:17:45.552 IPC Server: Info: Client 0 successfully registered RPC method "managementCaExists" (this method is registered by 1 client(s)).
09/30/20 22:17:45.553 IPC Server: Info: Client 0 successfully registered RPC method "managementCreateCa" (this method is registered by 1 client(s)).
09/30/20 22:17:45.553 IPC Server: Info: Client 0 successfully registered RPC method "managementCreateCert" (this method is registered by 1 client(s)).
09/30/20 22:17:45.554 IPC Server: Info: Client 0 successfully registered RPC method "managementDeleteCert" (this method is registered by 1 client(s)).
09/30/20 22:17:45.555 IPC Server: Info: Client 0 successfully registered RPC method "managementGetNetworkConfiguration" (this method is registered by 1 client(s)).
09/30/20 22:17:45.556 IPC Server: Info: Client 0 successfully registered RPC method "managementSetNetworkConfiguration" (this method is registered by 1 client(s)).
09/30/20 22:17:45.557 IPC Server: Info: Client 0 successfully registered RPC method "managementCopyDeviceDescriptionFile" (this method is registered by 1 client(s)).
09/30/20 22:17:45.558 IPC Server: Info: Client 0 successfully registered RPC method "managementUploadDeviceDescriptionFile" (this method is registered by 1 client(s)).
09/30/20 22:17:58.994 RPC Server (Port 2001): Info: Client number 7 is calling RPC method: init (2) Parameters:
(String) binary://192.168.1.15:9126
09/30/20 22:17:58.996 Info: Client with IP ::ffff:192.168.1.15 is calling "init".
09/30/20 22:17:59.013 RPC Server (Port 2001): Info: Connection from ::ffff:192.168.1.15:56644 accepted. Client number: 10
09/30/20 22:17:59.013 RPC Server (Port 2001): Info: RPC server client id for client number 10 is: 1
09/30/20 22:17:59.014 RPC Server (Port 2001): Info: Client number 10 is calling RPC method: init (2) Parameters:
(String) binary://192.168.1.15:9126
(String) RF-F80C2E2A-2795-DA83-F307-9A029251254E
(Integer) 34
09/30/20 22:17:59.015 Info: Client with IP ::ffff:192.168.1.15 is calling "init".
09/30/20 22:17:59.015 Info: Adding server "binary://192.168.1.15".
09/30/20 22:17:59.015 Info: Calling init methods on server "binary://192.168.1.15".
09/30/20 22:17:59.027 RPC Server (Port 2001): Info: Connection from ::ffff:192.168.1.15:56646 accepted. Client number: 11
09/30/20 22:17:59.027 RPC Server (Port 2001): Info: RPC server client id for client number 11 is: 2
09/30/20 22:17:59.029 RPC Server (Port 2001): Info: Client number 11 is calling RPC method: ping (2) Parameters:
(String) F80C2E2A-2795-DA83-F307-9A029251254E
09/30/20 22:17:59.035 RPC Server (Port 2001): Info: Client number 11 is calling RPC method: listBidcosInterfaces (2) Parameters:
09/30/20 22:17:59.527 Debug: Adding method system.multicall
09/30/20 22:17:59.528 Debug: Adding method event
09/30/20 22:17:59.528 Debug: Adding method deleteDevices
09/30/20 22:17:59.528 Debug: Adding method newDevices
09/30/20 22:18:01.348 MAX packet received (KITCHEN-MAX-CUL, RSSI: 0x5D): 0C780442136E88107C250022CA
09/30/20 22:18:01.396 MAX packet received (KITCHEN-MAX-CUL, RSSI: 0x54): 0E780202107C25136E880001190022
09/30/20 22:18:14.053 RPC Server (Port 2001): Info: Client number 11 is calling RPC method: ping (2) Parameters:
(String) F80C2E2A-2795-DA83-F307-9A029251254E
09/30/20 22:18:14.061 RPC Server (Port 2001): Info: Client number 11 is calling RPC method: listBidcosInterfaces (2) Parameters:
09/30/20 22:18:29.073 RPC Server (Port 2001): Info: Client number 11 is calling RPC method: ping (2) Parameters:

I have tried the higher debug level, and it didn’t appear to show any errors or problems - just an awful lot more information. Quite happy to do it again though, I’ll make a separate post for that as it’s a lot of info.

PaulL · September 30, 2020, 10:17am

OK, updated max.conf to a responseDelay back to 40, and debug level to 5. Uploading the full log file from that run, from startup.

homegear.log (78.1 KB)

Still the same behaviour. What I really don’t understand is why it worked for a while and then stopped. I don’t believe I changed anything at all, other than that I did make a config change in my openhab rules that resulted in my running into the sending limit, and it hasn’t worked again since then. Is it possible that I ran out of sending credits once, and it has somehow persisted that and isn’t sending? It shows no indication of that, since it clearly tells me when I’m out of sending credits, but it’s the only thing I can point to that happened around the time it stopped.

pmayer · September 30, 2020, 10:42am

Thanks for that detailed debugging.

One thing that catched my eye:

09/30/20 22:17:36.549 Info: Loading settings from /etc/homegear/families/max.conf
09/30/20 22:17:36.550 Error: Physical interface with title "general" has no type or id set. Please control your settings in "/etc/homegear/families/max.conf".

Could you try to check for this error?

Sim · September 30, 2020, 11:44am

pmayer:

09/30/20 22:17:36.549 Info: Loading settings from /etc/homegear/families/max.conf
09/30/20 22:17:36.550 Error: Physical interface with title "general" has no type or id set. Please control your settings in "/etc/homegear/families/max.conf".

Isn’t that caused by the same issue we already had this week?

rolandw · September 30, 2020, 1:33pm

“Physical interface with title “general” has no type or id set.” is just a false positive that has already been fixed by one of the developers due to a missing exception for the [General] section for a recently added check.

What I cannot answer is when this fix will be merged to master and included in the next nightly or release version.

PaulL · September 30, 2020, 5:49pm

OK, if that "Physical interface with title “general”’ error is unrelated (and not fixable), are there any other suggestions for what could be going on? If not, is there more debugging that could be done?

I was trying to work out if there’s a way to sniff everything going to the /dev/ttyACM0 port, as that would tell me if it’s failing to write to the port at all, or if any error is more likely to be OS level or hardware level. I saw some suggestion around strace, but it looked a little unclear on whether that actually works with a tty port.

PaulL · October 1, 2020, 1:50am

OK, did a full reinstall this morning. Takes longer than you’d think. Works straight away, no issues. No idea what’s different.