search

mysensors / MySensors

MySensors library and examples
https://www.mysensors.org
1.32k stars 895 forks source link

Recursive call of process() and wait() when using signing #1458

Open tobof opened 3 years ago

tobof commented 3 years ago

Version tested: 2.3.2 / 2.4-alpha

Version 2.3.0 does not produce this error / debug message.

RPI gateway configured with:

./configure 
--my-transport=rfm69 
--my-rfm69-frequency=868 
--my-is-rfm69hw 
--my-gateway=mqtt 
--my-controller-ip-address=192.168.2.13 
--my-mqtt-publish-topic-prefix=mysensors-out 
--my-mqtt-subscribe-topic-prefix=mysensors-in 
--my-mqtt-client-id=mygateway1 
--my-signing=software

The gateway itself works but fires a lot DEBUG !MCO:PRO:RC=1 messages before a message is passed to the mysensors network. Receiving messages works fine.

Debug log:

Dec 02 16:08:08 INFO  Starting gateway...
Dec 02 16:08:08 INFO  Protocol version - 2.3.2
Dec 02 16:08:08 DEBUG MCO:BGN:INIT GW,CP=RPNGLS--,FQ=NA,REL=255,VER=2.3.2
Dec 02 16:08:08 DEBUG TSF:LRT:OK
Dec 02 16:08:08 DEBUG TSM:INIT
Dec 02 16:08:08 DEBUG TSF:WUR:MS=0
Dec 02 16:08:08 DEBUG TSM:INIT:TSP OK
Dec 02 16:08:08 DEBUG TSM:INIT:GW MODE
Dec 02 16:08:08 DEBUG TSM:READY:ID=0,PAR=0,DIS=0
Dec 02 16:08:08 DEBUG MCO:REG:NOT NEEDED
Dec 02 16:08:08 DEBUG MCO:BGN:STP
Dec 02 16:08:08 DEBUG MCO:BGN:INIT OK,TSP=1
Dec 02 16:08:08 DEBUG GWT:RMQ:CONNECTING...
Dec 02 16:08:08 DEBUG connected to 192.168.2.13
Dec 02 16:08:08 DEBUG GWT:RMQ:OK
Dec 02 16:08:08 DEBUG GWT:TPS:TOPIC=mysensors-out/0/255/0/0/18,MSG SENT
Dec 02 16:08:08 DEBUG TSM:READY:NWD REQ
Dec 02 16:08:08 DEBUG ?TSF:MSG:SEND,0-0-255-255,s=255,c=3,t=20,pt=0,l=0,sg=0,ft=0,st=OK:
Dec 02 16:08:08 DEBUG TSF:MSG:READ,99-99-0,s=255,c=3,t=21,pt=1,l=1,sg=0:0
Dec 02 16:08:08 DEBUG GWT:TPS:TOPIC=mysensors-out/99/255/3/0/21,MSG SENT
Dec 02 16:08:08 DEBUG TSF:MSG:READ,0-99-255,s=255,c=3,t=20,pt=0,l=0,sg=0:
Dec 02 16:08:08 DEBUG TSF:MSG:BC
Dec 02 16:08:09 DEBUG TSF:MSG:READ,0-98-255,s=255,c=3,t=20,pt=0,l=0,sg=0:
Dec 02 16:08:09 DEBUG TSF:MSG:BC
Dec 02 16:08:10 DEBUG TSF:MSG:READ,98-99-0,s=255,c=3,t=21,pt=1,l=1,sg=0:99
Dec 02 16:08:10 DEBUG GWT:TPS:TOPIC=mysensors-out/98/255/3/0/21,MSG SENT
Dec 02 16:08:10 DEBUG TSF:MSG:READ,0-97-255,s=255,c=3,t=20,pt=0,l=0,sg=0:
Dec 02 16:08:10 DEBUG TSF:MSG:BC
Dec 02 16:08:10 DEBUG TSF:MSG:READ,97-99-0,s=255,c=3,t=21,pt=1,l=1,sg=0:98
Dec 02 16:08:10 DEBUG GWT:TPS:TOPIC=mysensors-out/97/255/3/0/21,MSG SENT
Dec 02 16:08:39 DEBUG TSF:MSG:READ,98-99-0,s=255,c=3,t=22,pt=5,l=4,sg=0:181035246
Dec 02 16:08:39 DEBUG GWT:TPS:TOPIC=mysensors-out/98/255/3/0/22,MSG SENT
Dec 02 16:08:42 DEBUG GWT:IMQ:TOPIC=mysensors-in/98/4/1/0/2, MSG RECEIVED
Dec 02 16:08:42 DEBUG TSF:MSG:SEND,0-0-99-98,s=4,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=OK:
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:42 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG !MCO:PRO:RC=1
Dec 02 16:08:43 DEBUG TSF:MSG:READ,98-99-0,s=255,c=3,t=17,pt=6,l=25,sg=0:<NONCE>
Dec 02 16:08:43 DEBUG TSF:MSG:SEND,0-0-99-98,s=4,c=1,t=2,pt=0,l=1,sg=1,ft=0,st=OK:1
Dec 02 16:08:46 DEBUG TSF:MSG:READ,97-99-0,s=255,c=3,t=22,pt=5,l=4,sg=0:181033345
Dec 02 16:08:46 DEBUG GWT:TPS:TOPIC=mysensors-out/97/255/3/0/22,MSG SENT
Yveaux commented 3 years ago

As discussed on the forum (https://forum.mysensors.org/topic/11462/mqtt-gw-with-rfm69-on-rpi), very likely related to signing, as it is reported to occur on different gateways, with different radios, when using signing.

Yveaux commented 3 years ago

Found the issue: Message signing requests a nonce using the _process() method, but this is called from within the same _process() method, hence the 1-level deep recursive call reported by "!MCO:PRO:RC=1": https://github.com/mysensors/MySensors/blob/01d8d10153d11cd064d3c7ace637bd9baac32bdb/core/MySigning.cpp#L220 https://github.com/mysensors/MySensors/blob/01d8d10153d11cd064d3c7ace637bd9baac32bdb/core/MySigning.cpp#L227

Yveaux commented 3 years ago

It appears to happen in more cases though, judging from logs on the forum:

Requesting nonce, log from gw:

47476 SGN:SKP:MSG CMD=3,TYPE=16
47482 TSF:MSG:SEND,0-0-123-123,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=OK:
47491 SGN:SGN:NCE REQ,TO=123
47493 !MCO:PRO:RC=1
47495 !MCO:PRO:RC=1

Logs from a node:

20301 TSM:UPL:OK
20303 TSM:READY:ID=33,PAR=0,DIS=1
20307 SGN:PRE:SGN REQ
20310 SGN:PRE:WHI NREQ
20312 SGN:SKP:MSG CMD=3,TYPE=15
20416 TSF:MSG:SEND,33-33-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0101
20424 SGN:PRE:XMT,TO=0
20426 SGN:PRE:WAIT GW
20430 !MCO:WAI:RC=1
20432 !MCO:PRO:RC=1
21161 TSF:MSG:READ,0-0-33,s=255,c=3,t=15,pt=6,l=2,sg=0:0101
21168 SGN:SKP:MSG CMD=3,TYPE=15
21170 SGN:PRE:SGN REQ,FROM=0
21174 SGN:SKP:MSG CMD=3,TYPE=16
22130 !TSF:MSG:SEND,33-33-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=NACK:
22136 !SGN:SGN:NCE REQ,TO=0 FAIL
22140 !TSF:MSG:SIGN FAIL
22142 SGN:SKP:MSG CMD=3,TYPE=16
23193 !TSF:MSG:SEND,33-33-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=2,st=NACK:
23199 !SGN:SGN:NCE REQ,TO=0 FAIL
23203 !TSF:MSG:SIGN FAIL
23205 !MCO:WAI:RC=1
23207 !MCO:PRO:RC=1
23212 !MCO:PRO:RC=1
anp369 commented 3 years ago

Are there any updates on this problem? right now I'm at the point to suspect that this is the problem that causes problems with my lights. The error seems to pop up when sending multiple messages to the gateway in a shorter time (for example when setting a scene). That may be related. Let me know if you would need more logs/debug scenarios, I would be glad to help out :)