Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
tobof opened this issue Dec 2, 2020 · 4 comments
Open

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

tobof opened this issue Dec 2, 2020 · 4 comments
Labels
bug

Comments

@tobof
Copy link

tobof commented Dec 2, 2020 •
edited
Loading

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
Copy link
Member

Yveaux commented Dec 3, 2020 •
edited
Loading

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 Yveaux added the bug label Dec 3, 2020
@Yveaux
Copy link
Member

Yveaux commented Dec 5, 2020 •
edited
Loading

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":

MySensors/core/MySigning.cpp

Line 220 in 01d8d10

SIGN_DEBUG(PSTR("SGN:SGN:NCE REQ,TO=%" PRIu8 "\n"), msg.getDestination()); // Nonce requested

MySensors/core/MySigning.cpp

Line 227 in 01d8d10

_process();

@Yveaux Yveaux changed the title !MCO:PRO:RC=1 with MQTT GW RFM69 on RPi Recursive call of process when requesting a nonce for signing Dec 5, 2020
@Yveaux
Copy link
Member

Yveaux commented Dec 5, 2020 •
edited
Loading

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

@Yveaux Yveaux changed the title Recursive call of process when requesting a nonce for signing Recursive call of process() when using signing Dec 5, 2020
@Yveaux Yveaux changed the title Recursive call of process() when using signing Recursive call of process() and wait() when using signing Dec 5, 2020
@anp369
Copy link

anp369 commented Jul 11, 2021

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 :)

@fallberg fallberg mentioned this issue Nov 9, 2021
Open
virtual-maker added a commit to virtual-maker/MySensors that referenced this issue Feb 14, 2022
@virtual-maker
WIP: Refactor wait() and _process() recursion (mysensors#1458)
eaf34cd
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Yveaux @tobof @anp369