MQTTClientGateway broken after upgrade - signature failure
-
I have just collected the log from the sensor node. I also removed a repeater node which I had out of the communication chain.
From the log it seems that the node requests a nonce but does not receive it, although the gateway seems to send one...
Increasing MY_VERIFICATION_TIMEOUT_MS to 15000 did change anything.
Starting sensor (RNNNAA, 2.0.0-beta) Radio init successful. Multisensor Sketch Type A - Battery Powered Temp/Humid/Light/Presence1.3 Setup temp/humid sensor completed Found light sensor - Online! Skipping security for command 3 type 16 send: 26-26-0-0 s=255,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Timeout waiting for nonce! sign fail send: 26-26-0-0 s=255,c=3,t=11,pt=0,l=25,sg=0,st=ok:Multisensor Sketch Type A Skipping security for command 3 type 16 send: 26-26-0-0 s=255,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Timeout waiting for nonce! sign fail send: 26-26-0-0 s=255,c=3,t=12,pt=0,l=3,sg=0,st=ok:1.3 Skipping security for command 3 type 16 send: 26-26-0-0 s=1,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Timeout waiting for nonce! sign fail send: 26-26-0-0 s=1,c=0,t=6,pt=0,l=0,sg=0,st=ok: Skipping security for command 3 type 16 send: 26-26-0-0 s=2,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Timeout waiting for nonce! sign fail send: 26-26-0-0 s=2,c=0,t=7,pt=0,l=0,sg=0,st=ok: Skipping security for command 3 type 16 send: 26-26-0-0 s=3,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Message to send could not be signed! sign fail send: 26-26-0-0 s=3,c=0,t=16,pt=0,l=0,sg=0,st=ok: Skipping security for command 3 type 16 send: 26-26-0-0 s=4,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Message to send could not be signed! sign fail send: 26-26-0-0 s=4,c=0,t=1,pt=0,l=0,sg=0,st=ok: Skipping security for command 3 type 16 send: 26-26-0-0 s=199,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Timeout waiting for nonce! sign fail send: 26-26-0-0 s=199,c=0,t=13,pt=0,l=0,sg=0,st=ok: isMetric: 1 lastTemperature: -100.00 lastHumidity: -100.00 TempDiff :127.42 HumDiff :120.93 Skipping security for command 3 type 16 send: 26-26-0-0 s=1,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Timeout waiting for nonce! sign fail send: 26-26-0-0 s=1,c=1,t=0,pt=7,l=5,sg=0,st=ok:27.4 Skipping security for command 3 type 16 send: 26-26-0-0 s=2,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Timeout waiting for nonce! sign fail send: 26-26-0-0 s=2,c=1,t=1,pt=7,l=5,sg=0,st=ok:20.9 IR: 1 Full: 2 Visible: 1 Lux: 1.00 Lux difference since last measurement: 1.00 Skipping security for command 3 type 16 send: 26-26-0-0 s=3,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Skipping security for command 3 type 17 read: 0-0-26 s=255,c=3,t=17,pt=6,l=25,sg=0:5333F4601AD619250DDA35ADEBB1E46F78EB96A1D769F33114 Nonce received from 0. Proceeding with signing... Signing backend: ATSHA204 Message to process: 1A002EE125030000803F01 Current nonce: 5333F4601AD619250DDA35ADEBB1E46F78EB96A1D769F33114AAAAAAAAAAAAAA HMAC: 51A6B54EB9C0BAF3A4F982216BC4764F2DD2810D74392BC952DDAA976C78A051 Signature in message: 01A6B54EB9C0BAF3A4F982216BC4764F2DD2810D Message signed Message to send has been signed send: 26-26-0-0 s=3,c=1,t=37,pt=7,l=5,sg=1,st=ok:1.0 Skipping security for command 3 type 16 send: 26-26-0-0 s=199,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Message to send could not be signed! sign fail send: 26-26-0-0 s=199,c=1,t=38,pt=4,l=4,sg=0,st=ok:1274 Skipping security for command 3 type 16 send: 26-26-0-0 s=255,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Message to send could not be signed! sign fail send: 26-26-0-0 s=255,c=3,t=0,pt=1,l=1,sg=0,st=ok:90 Signing required Skipping security for command 3 type 15 send: 26-26-0-0 s=255,c=3,t=15,pt=0,l=2,sg=0,st=ok: Waiting for GW to send signing preferences... Skipping security for command 3 type 15 read: 0-0-26 s=255,c=3,t=15,pt=0,l=2,sg=0: Mark node 0 as one that require signed messages Mark node 0 as one that do not require whitelisting Skipping security for command 3 type 16 send: 26-26-0-0 s=255,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Timeout waiting for nonce! sign fail send: 26-26-0-0 s=255,c=0,t=17,pt=0,l=10,sg=0,st=ok:2.0.0-beta Skipping security for command 3 type 16 send: 26-26-0-0 s=255,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Skipping security for command 3 type 17 read: 0-0-26 s=255,c=3,t=17,pt=6,l=25,sg=0:BDFF3B5B9BC735ADF4C3375DE3B98A0BD45BCB30469DC8D4F3 Nonce received from 0. Proceeding with signing... Signing backend: ATSHA204 Message to process: 1A000E2306FF00 Current nonce: BDFF3B5B9BC735ADF4C3375DE3B98A0BD45BCB30469DC8D4F3AAAAAAAAAAAAAA HMAC: 6B2DE4B7DCB4F5D4691AD3979CEA4D6DD80D8E1D0D8A659906D9F0B0B9497C66 Signature in message: 012DE4B7DCB4F5D4691AD3979CEA4D6DD80D8E1D0D8A6599 Message signed Message to send has been signed send: 26-26-0-0 s=255,c=3,t=6,pt=1,l=1,sg=1,st=ok:0 Init complete, id=26, parent=0, distance=1 lastTemperature: 27.42 lastHumidity: 20.93 TempDiff :0.04 HumDiff :0.43 IR: 1 Full: 2 Visible: 1 Lux: 1.00 Lux difference since last measurement: 0.00 Tripped: 1 Skipping security for command 3 type 16 send: 26-26-0-0 s=4,c=3,t=16,pt=0,l=0,sg=0,st=ok: Nonce requested from 0. Waiting... Message to send could not be signed! sign fail send: 26-26-0-0 s=4,c=1,t=16,pt=0,l=1,sg=0,st=ok:1 -
Try increasing the timeout for the nonce. I don't know if MQTT logic results in a longer turnaround time for message processing.
-
@Anticimex I increased MY_VERIFICATION_TIMEOUT_MS to 15s. Isn't that the nonce timeout?
-
@Anticimex nonce requested from node 0 looks suspicious. Is that the correct node id?
-
@Anticimex Isn't node 0 the gateway node id? If not that might be something to follow up on.
-
Ah, it's the GW. But I see from gw log that you get st=fail on the nonce so the GW does try to send it but your node does not receive it. So you have communication problems. Bear in mind that with signing, the full payload size is used, which puts maximum strain on the rf link so you have to have a solid coverage.
-
@Anticimex Both node were lying side by side. And I had my small network working perfectly on an older dev branch. So I don't think it can be due to coverage or distance.
Arghhh: I an only post once within 2 minutes... -
@Anticimex Both node were lying side by side. And I had my small network working perfectly on an older dev branch. So I don't think it can be due to coverage or distance.
Arghhh: I an only post once within 2 minutes...@tomkxy well, your logs indicate signing works as it's supposed to. But the nonce fails to arrive, and this is also indicated by st=fail, so you have a radio issue. You probably get problems without signing as well if you transmit full length messages.
-
@Anticimex Both node were lying side by side. And I had my small network working perfectly on an older dev branch. So I don't think it can be due to coverage or distance.
Arghhh: I an only post once within 2 minutes... -
@Anticimex I will try it further apart. But I have other nodes having the same problem and they are sitting exactly where they were before the upgrade. The only thing I changed for the sensors is to re-compile with the latest development branch for the sensor nodes.
Only the MQTTClientGateway was running a sketch based on a rather "old" version. So that upgrade is significant.
-
Depending on the "leap" you have taken some changes in the rf stack could have affected things. The signing solution have been changed but it has not affected payload sizes so I do not think signing is causing this (other than forcing maximum payload sizes which it has all along).
-
@Anticimex I just tried to disable signing on the gateway and on the sensor and it works like a charme.
So I still hope there is some issue either in my sketch (defines etc.) or a bug. Without signing I do not consider MySensors for me as an option. :-( -
@Anticimex I just tried to disable signing on the gateway and on the sensor and it works like a charme.
So I still hope there is some issue either in my sketch (defines etc.) or a bug. Without signing I do not consider MySensors for me as an option. :-(@tomkxy like I said, from the logs I see nothing wrong with signing. But your nonce is not coming through due to rf issue. I have verified signing on development branch myself (since I developed it) so I am confident it works. But it is well known that rf performance is decreasing with increased message size and I assume you don't use full size transmissions with signing disabled. So I would suggest you check rf decoupling, PA levels and antennae. It is also known that keeping radios too close can cause bursts which appear as failed transmissions but I am no specialist in those areas. Signing assume a ideal transport mechanisms, so you have to ensure there are no st=fail:s for signing related messages. The signing backend cannot handle those for you.
-
@Anticimex thanks for your support. Don't get me wrong I think MySensors and the whole signing concept is great. It is just somehow frustrating to see how a whole installation - even small until now - which worked for more than half a year is just breaking down while not having a glue what I can do about it.
What in particular are you referring to with reference to rf decoupling?
Just wondering how does your config look like?
What radios? What configs? -
@Anticimex thanks for your support. Don't get me wrong I think MySensors and the whole signing concept is great. It is just somehow frustrating to see how a whole installation - even small until now - which worked for more than half a year is just breaking down while not having a glue what I can do about it.
What in particular are you referring to with reference to rf decoupling?
Just wondering how does your config look like?
What radios? What configs?@tomkxy I use rf24 with default settings (except some moved io pins) and a PA-enhanced radio on the GW. But getting the rf24 to behave can be tricky. And the larger the message, the trickier it gets. Unfortunately this means it gets trickiest with signing enabled as it makes most messages very large (thus making them more sensitive to rf disturbance). Unfortunately, it is not much I can do about it from a signing perspective. Reducing the message size for signatures and nonces or adding fault tolerance to the security messages compromises security quality, and I already to that with the truncation of the signatures (due to rf24 limitations) so I don't want to "nerf" if further. So the signing solution is quite rf sensitive. But the way I see it, that just serves as a good measure for the overall quality of the rf network. If it works with shorter messages, sooner or later, maybe you add a node that transmits longer messages and start to get issues. With signing enabled, you are forced to root out any lingering rf issues immediately, and is saved from unpleasant surprises later on. But of course I understand the frustration, having experienced it myself several times. But st=fail is not a signing problem, it is a rf problem. So I am afraid I am not the best resource to provide answers. @tekka has made an excellent pull request where he has optimized the rf24 stack significantly. Perhaps applying it could help solve your rf issue: https://github.com/mysensors/Arduino/pull/392
-
@Anticimex I fully agree to your judgement that the problem is not due to the signing as such. However, I also do not believe in the RF24 issue. I tried with a CUSTOM child and using the max payload size available which without signing went through.
I think there might be an issue related to the changed code pathes which is caused by "injecting" signing or a define or whatsoever in my sketch is wrong after the upgrade.
I tried @tekka pull request with the result that nothing arrived at the gateway at all.
Do you know why hardware signing is not supported in the MQTTClientGateway?
-
@Anticimex I fully agree to your judgement that the problem is not due to the signing as such. However, I also do not believe in the RF24 issue. I tried with a CUSTOM child and using the max payload size available which without signing went through.
I think there might be an issue related to the changed code pathes which is caused by "injecting" signing or a define or whatsoever in my sketch is wrong after the upgrade.
I tried @tekka pull request with the result that nothing arrived at the gateway at all.
Do you know why hardware signing is not supported in the MQTTClientGateway?
@tomkxy Both hardware and software signing has no knowledge about MQTT. They only handle signatures of messages passed between gw and nodes. How the gw communicates with controller is irrelevant. Unless MQTT messes up how gw adresses nodes, I cannot see how signing could not work for MQTT. And if it does, it is a bug in MQTT implementation and not signing.
-
@Anticimex I did not want to suggest that it is a bug in signing, I just referred to the comment in the W5100MQTTClientGateway sketch saying "Hardware SHA204 signing is currently not supported" and was wondering whether you know why.
Sorry for bothering you on that. As I said I agree that the problem must somehow be related to transmission.
