MAX CUL Unknown Message

[Bob B]

I have an RPi, CUL and two MAX! eQ3 rad thermostats; all are working well.
An extract from my logfile:
2016.11.23 19:35:51 2: CUL_0: unknown message ? (139ad3 is unknown) Use one of B b ...
2016.11.23 19:35:51 2: CUL_0: unknown message ? (8004520452045204520 is unknown) Use one of B b ...

There are many such messages.
The device 139ad3 is indeed unknown - my eQ3s ID's are 131ab2 and 130b46.

Sometimes the same messages are repeated verbatim several times a day*.
The unknown device ID changes so I get several messages for say, 139ad3, and then, hours later, it will be 01aed6. The thing is, it's repeated several times  so not caused by corruption.

So far I've tracked the "is unknown" message down to the CUL firmware ( culfw-1.66/clib/ttydata.c line:59). It seems as though fhem is sending these messages to CUL and having them rejected. Why would it do that?

I thought I'd ask if anyone has any ideas where these messages might come from before I continue.

Bob
* Note: There are some rare, uncorrelated occasions when the device is not recognised at all:
2016.11.23 17:05:42 2: CUL_0: unknown message ? ( is unknown) ...
This is a precursor to /dev/ttyACM0 disappearing and reappearing due, IMHO, to a Debian/Raspbian USB bug and I believe is a  red herring.

[rudolfkoenig]

It seems as though fhem is sending these messages

Can you please set the verbose attribute of the corresponding CUL-Device in FHEM to 5, and check the "SW:" lines in the fhem.log before the message comes up? Ist there another program writing to the same serial port?

[Bob B]

Many thanks Rudolf, I've set CUL_0 attr verbose to 5 and will report back as soon as something interesting occurs.
The RPi is running standard Raspbian with no extra services or apps that would write anything to /dev/ttyACM0 that I know of.
lsof just shows fhem holding /dev/ttyACM0 open.
Bob

[Bob B]

Rudolf,

I have attached a text extract of my log. The extract runs from just before the first error occurred after setting CUL_0 verbose = 5.

For what it's worth:
1) It looks like something to do with MaxScanner (?) as the error always seems to occur after lines like:
2016.11.30 02:28:38 3: MaxScanner MAX_LivingRoom Work.1228 <<set MAX_LivingRoom desiredTemperature  14.0>>
2016.11.30 02:28:38 3: MaxScanner ms Work.1324  next scan in seconds : 24
2016.11.30 02:28:38 5: CUL/RAW: /? (01aed9 is unknown) Use one of ...

2) I had trouble with MaxScanner last week.
For mechanical reasons I had to physically swap the thermostats between LivingRoom and SmallestBedroom.
In fhem.cfg I manually swapped their definitions:
define MAX_LivingRoom MAX HeatingThermostat 131ab2           --> define MAX_LivingRoom MAX HeatingThermostat 130b46
define MAX_SmallestBedroom MAX HeatingThermostat 130b46 --> define MAX_SmallestBedroom MAX HeatingThermostat 131ab2

When I restarted fhem I got messages saying something like "Cannot have two instances of MaxScanner" which was surprising as there was only one definition in fhem.cfg:
define ms MaxScanner
attr ms scnMinInterval 6

To get things working again I used FHEMWEB. There was no trace of "ms". I checked fhem.cfg and "define ms MaxScanner" had been deleted.
I defined it again (through FHEMWEB), set scnMinInterval and after a few minutes it started processing normally.

Any thought gratefully received!
Bob

[fruit]

2) I had trouble with MaxScanner last week.
For mechanical reasons I had to physically swap the thermostats between LivingRoom and SmallestBedroom.
In fhem.cfg I manually swapped their definitions:

I don't claim to know much about this module as I've only recently started using it but it does seem to be particular about how things are done with it!

When I restarted fhem I got messages saying something like "Cannot have two instances of MaxScanner" which was surprising as there was only one definition in fhem.cfg:

I've seen that too after rereadcfg and similar. A standard shutdown restart is fine and does not show this

To get things working again I used FHEMWEB. There was no trace of "ms". I checked fhem.cfg and "define ms MaxScanner" had been deleted.
I defined it again (through FHEMWEB), set scnMinInterval and after a few minutes it started processing normally.

That's the way you should be configuring fhem. If you don't things may break and can be difficult to fix - many of us have been there and learned the hard way - and we all thought we knew what we were doing! MaxScanner may need more care in this respect perhaps

I suggest you save your current config (from the web pages) and issue shutdown restart. See if that makes any difference to your logs

[rudolfkoenig]

I have no experience with MAX, just with culfw in general.
As your log does not show any SW: messages, FHEM is not sending this data to the culfw. I see two possibilities:
- a culfw bug. This is not very likely, as you were the first to report it. I checked culfw/clib/rf_moritz.c, and I think it is not guilty.
- another process writing to the CUL device. I would check that with "lsof | grep /dev/" as root.
Btw. 4004520452045204520 is ASCII @RRR with crtl-4 inserted after each character. In case somebody knows what this is.

[Bob B]

I don't claim to know much about this module as I've only recently started using it but it does seem to be particular about how things are done with it!I've seen that too after rereadcfg and similar. A standard shutdown restart is fine and does not show thisThat's the way you should be configuring fhem. If you don't things may break and can be difficult to fix - many of us have been there and learned the hard way - and we all thought we knew what we were doing! MaxScanner may need more care in this respect perhaps

I suggest you save your current config (from the web pages) and issue shutdown restart. See if that makes any difference to your logs

Hi fruit and thanks for the ever welcome help. I have done a shutdown restart now and await the results with interest. If there's no change I shall delete ms and the HeaterThermostats and start over again. I have just received another 7 eQ3 TRVs and don't fancy setting them up  until everything is OK with MaxScanner.

As far as manually editing the fhem.cfg file is concerned, well what can I say? Mea culpa. I'd read lots of warnings about it (probably yours) but it was such a tiny change - what could possibly go wrong? I'm sending off for an "I did it my way" tee shirt.
Bob

[Bob B]

I have no experience with MAX, just with culfw in general.
As your log does not show any SW: messages, FHEM is not sending this data to the culfw. I see two possibilities:
- a culfw bug. This is not very likely, as you were the first to report it. I checked culfw/clib/rf_moritz.c, and I think it is not guilty.
- another process writing to the CUL device. I would check that with "lsof | grep /dev/" as root.
Btw. 4004520452045204520 is ASCII @RRR with crtl-4 inserted after each character. In case somebody knows what this is.

Thanks for looking Rudolf. I've checked with lsof and no-one else uses the CUL stick so it's a mystery!
Bob

[Bob B]

Just for completeness the "shutdown restart" didn't really make any difference.
Subjectively, it seems there are fewer "CUL_0 unknown message" lines on their own in the log; the majority now are followed by the wretched "/dev/ttyACM0 disconnected" error. Giving up, moving on!

[Bob B]

I moved the CUL from a powered hub to a port directly on the RPi.
After 1 day there's not a single "unknown message" in the log. That's never happened before.

I suspect Debian/Raspbian/RPi or my hub was the culprit as I have seen other references to modem / tty ports misbehaving on hubs - nothing to do with fhem or CUL.