[security] Introducing signing support to MySensors

Anticimex

@alexsh1 has the node and gateway successfully exchanged their signing preferences? It is done at node startup.

alexsh1

@Anticimex No, straight at the beginning I got this:

0 MCO:BGN:INIT NODE,CP=RNONAA-,VER=2.1.1
4 TSM:INIT
4 TSF:WUR:MS=0
12 TSM:INIT:TSP OK
14 TSM:INIT:STATID=6
16 TSF:SID:OK,ID=6
18 TSM:FPAR
20 Will not sign message for destination 255 as it does not require it
61 TSF:MSG:SEND,6-6-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
538 TSF:MSG:READ,0-0-6,s=255,c=3,t=8,pt=1,l=1,sg=0:0
544 Skipping security for command 3 type 8
548 TSF:MSG:FPAR OK,ID=0,D=1
2070 TSM:FPAR:OK
2070 TSM:ID
2072 TSM:ID:OK
2074 TSM:UPL
2076 Will not sign message for destination 0 as it does not require it
2086 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2103 TSF:MSG:READ,0-0-6,s=255,c=3,t=25,pt=1,l=1,sg=0:1
2109 Skipping security for command 3 type 25
2115 TSF:MSG:PONG RECV,HP=1
2117 TSM:UPL:OK
2119 TSM:READY:ID=6,PAR=0,DIS=1
2123 ‘"Yð·�æ–à”]-”ô*“"2125 TSM:INIT
2 MCO:BGN:INIT NODE,CP=RNONAA-,VER=2.1.1```

Anticimex

@alexsh1 is that all? It looks like it has not reached the signing setup part yet. Is node and gw alive or are one of them hanging?

alexsh1

@Anticimex Yes, I am afraid. The GW is showing
"0;255;3;0;9;Message is not signed, but it should have been!
0;255;3;0;9;!TSF:MSG:SIGN VERIFY FAIL"

Yes, both node and GW are fine, but messages are not reaching the GW as signing is required.

Anticimex

@alexsh1 at startup of the node, it sends its signing preferences to the GW (assuming you have selected a signing backend, atsha204a or soft signing). The GW will then reply with its own preference to inform the node that it should sign messages. If the GW said that it rejects messages because they are unsigned, it suggests that the GW require signatures from that node, but the node does not realize that it needs to sign them. So either the node is not properly configured to sign messages or there have been a radio issue preventing message exchange during startup.

alexsh1

@Anticimex After forcing all nodes to sign with #define MY_SIGNING_GW_REQUEST_SIGNATURES_FROM_ALL
got this:

0 MCO:BGN:INIT NODE,CP=RNNNAA-,VER=2.1.1
4 TSM:INIT
4 TSF:WUR:MS=0
12 TSM:INIT:TSP OK
14 TSM:INIT:STATID=6
16 TSF:SID:OK,ID=6
18 TSM:FPAR
18 Will not sign message for destination 255 as it does not require it
61 TSF:MSG:SEND,6-6-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
1044 TSF:MSG:READ,0-0-6,s=255,c=3,t=8,pt=1,l=1,sg=0:0
1050 TSF:MSG:FPAR OK,ID=0,D=1
2070 TSM:FPAR:OK
2070 TSM:ID
2072 TSM:ID:OK
2074 TSM:UPL
2076 Skipping security for command 3 type 24
2082 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2103 TSF:MSG:READ,0-0-6,s=255,c=3,t=25,pt=1,l=1,sg=0:1
2109 TSF:MSG:PONG RECV,HP=1
2113 TSM:UPL:OK
2115 TSM:READY:ID=6,PAR=0,DIS=1
2117 Skipping security for command 3 type 15
2123 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
2131 Waiting for GW to send signing preferences...
2164 TSF:MSG:READ,0-0-6,s=255,c=3,t=15,pt=6,l=2,sg=0:0101
2170 Mark node 0 as one that require signed messages
2177 Mark node 0 as one that do not require whitelisting
2183 Skipping security for command 3 type 16
2189 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=OK:
2197 Nonce requested from 0. Waiting...
2201 Message to send could not be signed!
2205 !TSF:MSG:SIGN FAIL
2207 Skipping security for command 3 type 16
2213 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=1,st=OK:
2222 Nonce requested from 0. Waiting...
2226 Message to send could not be signed!
2230 !TSF:MSG:SIGN FAIL
2232 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:A03E832C91BD0CC2C02E2A16D834F9CA91816D234ABB1188A2
2244 Nonce received from 0.
2246 Proceeding with signing...
Message to process: 06000E2306FF00
Current nonce: A03E832C91BD0CC2C02E2A16D834F9CA91816D234ABB1188A2AAAAAAAAAAAAAA
HMAC: AF54D68677672C45B3E1329A9A1B4E7517D0A0FF340569C633D5DC52207F8DDA
Signature in message: 0154D68677672C45B3E1329A9A1B4E7517D0A0FF340569C6
2371 Message signed
2379 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:C1FACC7B2E3B538E31853CB92C73A87E3240FBC2253CE63A9E
2392 Nonce received from 0.
2394 Proceeding with signing...
Message to process: 06000E2306FF00
Current nonce: C1FACC7B2E3B538E31853CB92C73A87E3240FBC2253CE63A9EAAAAAAAAAAAAAA
HMAC: 9EE43EA4A510354CB2D3A0AB2C0D13D106CD9B666103E7B7115B73B646DB20DD
Signature in message: 01E43EA4A510354CB2D3A0AB2C0D13D106CD9B666103E7B7
2519 Message signed
4233 Skipping security for command 3 type 16
4239 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=1,st=OK:
4247 Nonce requested from 0. Waiting...
4280 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:25E2116C25EBB38BB5F87AFFC892073803D818F07FB1E36738
4292 Nonce received from 0.
4294 Proceeding with signing...
4298 Failed to sign message!
4300 Message to send could not be signed!
4304 !TSF:MSG:SIGN FAIL
4306 Skipping security for command 3 type 16
4315 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=1,st=OK:
4321 Nonce requested from 0. Waiting...
4354 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:6FE06CCBD9098A24D65907C9C7CF62062DA365227E5A836108
4366 Nonce received from 0.
4368 Proceeding with signing...
Message to process: 06001E030CFF312E31
Current nonce: 6FE06CCBD9098A24D65907C9C7CF62062DA365227E5A836108AAAAAAAAAAAAAA
HMAC: 564EF68106E0B7333A233F7C396BEDBE537F9AF012C78856F3BD37753B9F096E
Signature in message: 014EF68106E0B7333A233F7C396BEDBE537F9AF012C7
4491 Message signed
4499 Message to send has been signed
4505 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=12,pt=0,l=3,sg=1,ft=0,st=OK:1.1
4513 Skipping security for command 3 type 16
4519 TSF:MSG:SEND,6-6-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
4528 Nonce requested from 0. Waiting...
4651 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:67AD75E666FB63B0A606CCA15003152448DE5D66C1EA34E541
4663 Nonce received from 0.
4665 Proceeding with signing...
Message to process: 060006000800
Current nonce: 67AD75E666FB63B0A606CCA15003152448DE5D66C1EA34E541AAAAAAAAAAAAAA
HMAC: 4901D9D648B90185224D2256EADC4C607543E698EC2252B7E88BAD91696824CB
Signature in message: 0101D9D648B90185224D2256EADC4C607543E698EC2252B7E8
4790 Message signed
4798 Message to send has been signed
4804 TSF:MSG:SEND,6-6-0-0,s=0,c=0,t=8,pt=0,l=0,sg=1,ft=0,st=OK:
4812 Skipping security for command 3 type 16
4818 TSF:MSG:SEND,6-6-0-0,s=1,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
4827 Nonce requested from 0. Waiting...
4950 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:44DC6983F5E93696CEFD0B73423B33946AE1BC3DC40F562012
4962 Nonce received from 0.
4964 Proceeding with signing...
Message to process: 060006000601
Current nonce: 44DC6983F5E93696CEFD0B73423B33946AE1BC3DC40F562012AAAAAAAAAAAAAA
HMAC: 4D37001CE6A4C2E5C7C5B8995C871DA6386E9C7ADD90D3AF36D83C98C1E98166
Signature in message: 0137001CE6A4C2E5C7C5B8995C871DA6386E9C7ADD90D3AF36
5091 Message signed
5099 Message to send has been signed
5105 TSF:MSG:SEND,6-6-0-0,s=1,c=0,t=6,pt=0,l=0,sg=1,ft=0,st=OK:
5113 Skipping security for command 3 type 16
5122 TSF:MSG:SEND,6-6-0-0,s=2,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
5128 Nonce requested from 0. Waiting...
5253 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:B6C405695A2B551DE4C1AFC02125F42528209A3DF9013820E2
5263 Nonce received from 0.
5267 Proceeding with signing...
Message to process: 060006000702
Current nonce: B6C405695A2B551DE4C1AFC02125F42528209A3DF9013820E2AAAAAAAAAAAAAA
HMAC: B767B39D7B5F78422608CCF763DA7C94B333DA95C07087D896DFB36CACF0CE77
Signature in message: 0167B39D7B5F78422608CCF763DA7C94B333DA95C07087D896
5392 Message signed
5398 Message to send has been signed
5404 TSF:MSG:SEND,6-6-0-0,s=2,c=0,t=7,pt=0,l=0,sg=1,ft=0,st=OK:
5412 Skipping security for command 3 type 16
5421 TSF:MSG:SEND,6-6-0-0,s=3,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
5427 Nonce requested from 0. Waiting...
5554 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:9A92C415D6BE672E588BE107BE88637D9D3551A029796C12EF
5566 Nonce received from 0.
5568 Proceeding with signing...
Message to process: 060006000D03
Current nonce: 9A92C415D6BE672E588BE107BE88637D9D3551A029796C12EFAAAAAAAAAAAAAA
HMAC: B75B0F0C356378B1EEC25726EE552581F98B1957ADE9A82EF48408FD528927E6
Signature in message: 015B0F0C356378B1EEC25726EE552581F98B1957ADE9A82EF4
5693 Message signed
5699 Message to send has been signed
5707 TSF:MSG:SEND,6-6-0-0,s=3,c=0,t=13,pt=0,l=0,sg=1,ft=0,st=OK:
5713 MCO:REG:REQ
5715 Skipping security for command 3 type 26
5724 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=26,pt=1,l=1,sg=1,ft=0,st=OK:2
5830 TSF:MSG:READ,0-0-6,s=255,c=3,t=27,pt=1,l=1,sg=0:1
5836 MCO:PIM:NODE REG=1
5838 MCO:BGN:STP
BME280 Pressure Sensor1.1isMetric: 1
6160 Skipping security for command 3 type 16
6168 TSF:MSG:SEND,6-6-0-0,s=3,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
6174 Nonce requested from 0. Waiting...
6207 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:F7F1A5F6C487947D093E7676AA05AF1BE65AFE31B4223034C2
6219 Nonce received from 0.
6221 Proceeding with signing...
Message to process: 06002EE12603EE7C4F4002
Current nonce: F7F1A5F6C487947D093E7676AA05AF1BE65AFE31B4223034C2AAAAAAAAAAAAAA
HMAC: DF2217C08446766ECC9CD41D4C9643B546CC921AEAA9E1971DF314F965D2D0FE
Signature in message: 012217C08446766ECC9CD41D4C9643B546CC921A
6346 Message signed
6354 Message to send has been signed
6361 TSF:MSG:SEND,6-6-0-0,s=3,c=1,t=38,pt=7,l=5,sg=1,ft=0,st=OK:3.24
6369 Skipping security for command 3 type 16
6377 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
6383 Nonce requested from 0. Waiting...
6508 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:027634E4197B49C4FDB8059CB6D34AA6D81EB340D934252BBF
6518 Nonce received from 0.
6522 Proceeding with signing...
Message to process: 06000E2300FF67
Current nonce: 027634E4197B49C4FDB8059CB6D34AA6D81EB340D934252BBFAAAAAAAAAAAAAA
HMAC: 572A1585F50CE39199035088548A9877A08B8B3FA8404FA31B8B55B5190320C1
Signature in message: 012A1585F50CE39199035088548A9877A08B8B3FA8404FA3
6645 Message signed
6651 Message to send has been signed
6660 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=0,pt=1,l=1,sg=1,ft=0,st=OK:103
6666 MCO:BGN:INIT OK,TSP=1
Temperature = 24.90 *C
Humidity = 48.62 %
Pressure = 994.33 hPa
Forecast = unknown
6678 Skipping security for command 3 type 16
6688 TSF:MSG:SEND,6-6-0-0,s=1,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
6696 Nonce requested from 0. Waiting...
6805 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:988D1BCE8B949E24FA8D7FE18200429C16B01AF0B927CE0709
6815 Nonce received from 0.
6819 Proceeding with signing...
Message to process: 06002EE1149307E4071493
Current nonce: 988D1BCE8B949E24FA8D7FE18200429C16B01AF0B927CE0709AAAAAAAAAAAAAA
HMAC: EAB0E2B8ECF6B95E6D07BE2651BECF977C53DDB8516DD847CFE6688DD61140ED
Signature in message: 01B0E2B8ECF6B95E6D07BE2651BECF977C53DDB8
6944 Message signed
6952 Message to send has been signed
6959 TSF:MSG:SEND,6-6-0-0,s=147,c=1,t=20,pt=7,l=5,sg=1,ft=0,st=OK:0.00000000
6967 Skipping security for command 3 type 16
6975 TSF:MSG:SEND,6-6-0-0,s=2,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
6981 Nonce requested from 0. Waiting...
6985 Message to send could not be signed!
6989 !TSF:MSG:SIGN FAIL
6993 Skipping security for command 3 type 16
7000 TSF:MSG:SEND,6-6-0-0,s=0,c=3,t=16,pt=0,l=0,sg=0,ft=1,st=OK:
7006 Nonce requested from 0. Waiting...
7010 Message to send could not be signed!
7014 !TSF:MSG:SIGN FAIL
7018 Skipping security for command 3 type 16
7024 TSF:MSG:SEND,6-6-0-0,s=0,c=3,t=16,pt=0,l=0,sg=0,ft=1,st=OK:
7030 Nonce requested from 0. Waiting...
7034 Message to send could not be signed!
7038 !TSF:MSG:SIGN FAIL
7092 MCO:SLP:MS=300000,SMS=0,I1=255,M1=255,I2=255,M2=255
7098 MCO:SLP:TPD

What do you think the problem is?
Why is it still MSG:SIGN FAIL

EDIT: this is the GW log:

0;255;3;0;9;MCO:BGN:INIT GW,CP=RNNGAS-,VER=2.1.1
0;255;3;0;9;TSM:INIT
0;255;3;0;9;TSF:WUR:MS=0
0;255;3;0;9;TSM:INIT:TSP OK
0;255;3;0;9;TSM:INIT:GW MODE
0;255;3;0;9;TSM:READY:ID=0,PAR=0,DIS=0
0;255;3;0;9;MCO:REG:NOT NEEDED
IP: 10.1.1.120
0;255;3;0;9;MCO:BGN:STP
0;255;3;0;9;MCO:BGN:INIT OK,TSP=1
0;255;3;0;9;TSF:MSG:READ,15-15-0,s=1,c=1,t=0,pt=7,l=5,sg=0:27.0
0;255;3;0;9;Message is not signed, but it should have been!
0;255;3;0;9;!TSF:MSG:SIGN VERIFY FAIL
0;255;3;0;9;TSF:MSG:READ,15-15-0,s=0,c=1,t=4,pt=7,l=5,sg=0:996
0;255;3;0;9;Message is not signed, but it should have been!
0;255;3;0;9;!TSF:MSG:SIGN VERIFY FAIL
0;255;3;0;9;TSF:MSG:READ,6-6-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSF:MSG:BC
0;255;3;0;9;TSF:MSG:FPAR REQ,ID=6
0;255;3;0;9;TSF:PNG:SEND,TO=0
0;255;3;0;9;TSF:CKU:OK
0;255;3;0;9;TSF:MSG:GWL OK
0;255;3;0;9;Skipping security for command 3 type 8
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=OK:0
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=24,pt=1,l=1,sg=0:1
0;255;3;0;9;Skipping security for command 3 type 24
0;255;3;0;9;TSF:MSG:PINGED,ID=6,HP=1
0;255;3;0;9;Skipping security for command 3 type 25
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=OK:1
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=15,pt=6,l=2,sg=0:0101
0;255;3;0;9;Skipping security for command 3 type 15
0;255;3;0;9;Mark node 6 as one that require signed messages
0;255;3;0;9;Mark node 6 as one that do not require whitelisting
0;255;3;0;9;Informing node 6 that we require signatures
0;255;3;0;9;Informing node 6 that we do not require whitelisting
0;255;3;0;9;Skipping security for command 3 type 15
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0101
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=16,pt=0,l=0,sg=0:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: BB0EE26FC4C35E155CA36591DFC8DF866D188923ADCCA99ED700000000000000
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=0,ft=0,st=OK:BB0EE26FC4C35E155CA36591DFC8DF866D188923ADCCA99ED7
0;255;3;0;9;Transmitted nonce
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=16,pt=0,l=0,sg=0:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: C62553080FACCBBA84B0BE05AEA1871324370BD8BBF431D38CAAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=0,ft=0,st=OK:C62553080FACCBBA84B0BE05AEA1871324370BD8BBF431D38C
0;255;3;0;9;Transmitted nonce
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=16,pt=0,l=0,sg=1:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: AA4BF678F8D0BE6885E67795A8D6E001CF8E0AFECD0D6146B0AAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:AA4BF678F8D0BE6885E67795A8D6E001CF8E0AFECD0D6146B0
0;255;3;0;9;Transmitted nonce
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=16,pt=0,l=0,sg=0:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: 6122BFB72296B95B45E44C2B4D43A3CE1C9D1F43F24137149AAAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=0,ft=0,st=OK:6122BFB72296B95B45E44C2B4D43A3CE1C9D1F43F24137149A
0;255;3;0;9;Transmitted nonce
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=12,pt=0,l=3,sg=1:1.1
0;255;3;0;9;Signature in message: 016583B112FED6ED3698EB4A4AE12B319ACC2755CF92
0;255;3;0;9;Message to process: 06001E030CFF312E31
0;255;3;0;9;Current nonce: 6122BFB72296B95B45E44C2B4D43A3CE1C9D1F43F24137149AAAAAAAAAAAAAAA
0;255;3;0;9;HMAC: DD6583B112FED6ED3698EB4A4AE12B319ACC2755CF9239836E845A5B3DD186FF
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=0,c=3,t=16,pt=0,l=0,sg=1:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: D3F6004F4966A6D33936AC7EBCEEBF9CE919AD644BFA33289AAAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:D3F6004F4966A6D33936AC7EBCEEBF9CE919AD644BFA33289A
0;255;3;0;9;Transmitted nonce
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=0,c=0,t=8,pt=0,l=0,sg=1:
0;255;3;0;9;Signature in message: 01CF6F511AAA6A0F2750F6437F3DEA644A13335E155EC94488
0;255;3;0;9;Message to process: 060006000800
0;255;3;0;9;Current nonce: D3F6004F4966A6D33936AC7EBCEEBF9CE919AD644BFA33289AAAAAAAAAAAAAAA
0;255;3;0;9;HMAC: D6CF6F511AAA6A0F2750F6437F3DEA644A13335E155EC944884A4A6D7C667140
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=1,c=3,t=16,pt=0,l=0,sg=1:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: E310DE1F44902508B12558EB2C3C51066F381572694AD4D7CEAAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:E310DE1F44902508B12558EB2C3C51066F381572694AD4D7CE
0;255;3;0;9;Transmitted nonce
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=1,c=0,t=6,pt=0,l=0,sg=1:
0;255;3;0;9;Signature in message: 012F140689293B434B043699F131C397F629633FD7D9E9D489
0;255;3;0;9;Message to process: 060006000601
0;255;3;0;9;Current nonce: E310DE1F44902508B12558EB2C3C51066F381572694AD4D7CEAAAAAAAAAAAAAA
0;255;3;0;9;HMAC: 942F140689293B434B043699F131C397F629633FD7D9E9D48992B327A0CB9BB8
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=2,c=3,t=16,pt=0,l=0,sg=1:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: 0EB8A85D42109C29EBE8E78BF9B8C66092845EB7D92AC1B381AAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:0EB8A85D42109C29EBE8E78BF9B8C66092845EB7D92AC1B381
0;255;3;0;9;Transmitted nonce
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=2,c=0,t=7,pt=0,l=0,sg=1:
0;255;3;0;9;Signature in message: 018D9FBD8E3E4730D1932EE4E4BB998B10B593631551BBB575
0;255;3;0;9;Message to process: 060006000702
0;255;3;0;9;Current nonce: 0EB8A85D42109C29EBE8E78BF9B8C66092845EB7D92AC1B381AAAAAAAAAAAAAA
0;255;3;0;9;HMAC: 798D9FBD8E3E4730D1932EE4E4BB998B10B593631551BBB575BEC03A5C759E36
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=3,c=3,t=16,pt=0,l=0,sg=1:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: F8F8706BAAAD66823E6048248088515F8083EB545EBAF8C1DFAAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:F8F8706BAAAD66823E6048248088515F8083EB545EBAF8C1DF
0;255;3;0;9;Transmitted nonce
0;255;3;0;9;TSF:MSG:READ,10-10-0,s=1,c=1,t=17,pt=5,l=4,sg=0:332
0;255;3;0;9;Message is not signed, but it should have been!
0;255;3;0;9;!TSF:MSG:SIGN VERIFY FAIL
0;255;3;0;9;TSF:MSG:READ,10-10-0,s=1,c=1,t=24,pt=5,l=4,sg=0:51270118
0;255;3;0;9;Message is not signed, but it should have been!
0;255;3;0;9;!TSF:MSG:SIGN VERIFY FAIL
0;255;3;0;9;TSF:MSG:READ,10-10-0,s=1,c=1,t=18,pt=7,l=5,sg=0:51270.1210
0;255;3;0;9;Message is not signed, but it should have been!
0;255;3;0;9;!TSF:MSG:SIGN VERIFY FAIL
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=3,c=0,t=13,pt=0,l=0,sg=1:
0;255;3;0;9;Signature in message: 0137F7F5A35542631C67BB42381A81FAB165AE75D7B5C7408F
0;255;3;0;9;Message to process: 060006000D03
0;255;3;0;9;Current nonce: F8F8706BAAAD66823E6048248088515F8083EB545EBAF8C1DFAAAAAAAAAAAAAA
0;255;3;0;9;HMAC: 1237F7F5A35542631C67BB42381A81FAB165AE75D7B5C7408F3EE91419294238
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=26,pt=1,l=1,sg=1:2
0;255;3;0;9;Skipping security for command 3 type 26
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=OK:
0;255;3;0;9;Nonce requested from 6. Waiting...
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=17,pt=6,l=25,sg=0:84A969C4138F0268D8E015A27E2306F288252601FE54AE62A6
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;Nonce received from 6.
0;255;3;0;9;Proceeding with signing...
0;255;3;0;9;Message to process: 00060E231BFF01
0;255;3;0;9;Current nonce: 84A969C4138F0268D8E015A27E2306F288252601FE54AE62A6AAAAAAAAAAAAAA
0;255;3;0;9;HMAC: DB6CBDAB2875D284BE0CEA1518B86988A8CE3DC36A0B38E4BF1A35C416295EB3
0;255;3;0;9;Signature in message: 016CBDAB2875D284BE0CEA1518B86988A8CE3DC36A0B38E4
0;255;3;0;9;Message signed
0;255;3;0;9;Message to send has been signed
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=27,pt=1,l=1,sg=1,ft=0,st=OK:1
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=3,c=3,t=16,pt=0,l=0,sg=1:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: D38475550145574228E4E252AB0608F22CFADB55C307F076C4AAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:D38475550145574228E4E252AB0608F22CFADB55C307F076C4
0;255;3;0;9;Transmitted nonce
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=3,c=1,t=38,pt=7,l=5,sg=1:3.29
0;255;3;0;9;Signature in message: 01A48C0E185B8B50EDA96A7C905C0778B16D2C78
0;255;3;0;9;Message to process: 06002EE126035C8F524002
0;255;3;0;9;Current nonce: D38475550145574228E4E252AB0608F22CFADB55C307F076C4AAAAAAAAAAAAAA
0;255;3;0;9;HMAC: 8BA48C0E185B8B50EDA96A7C905C0778B16D2C78707A2959F86F0DBAF3FFE851
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=16,pt=0,l=0,sg=1:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: 028248EABB9E64FD89808ED98032CB650D3DCB81525A43BB31AAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:028248EABB9E64FD89808ED98032CB650D3DCB81525A43BB31
0;255;3;0;9;Transmitted nonce
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=255,c=3,t=0,pt=1,l=1,sg=1:106
0;255;3;0;9;Signature in message: 01D5CB11EFD24211E2CDCED741211AE9FF3E0AFE0AA9BBEE
0;255;3;0;9;Message to process: 06000E2300FF6A
0;255;3;0;9;Current nonce: 028248EABB9E64FD89808ED98032CB650D3DCB81525A43BB31AAAAAAAAAAAAAA
0;255;3;0;9;HMAC: F5D5CB11EFD24211E2CDCED741211AE9FF3E0AFE0AA9BBEE96970EB2EF247BB5
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=1,c=3,t=16,pt=0,l=0,sg=1:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: 6DE60F283CD99033EEC6DF5DE044BE08F5151149E6DFD04FEAAAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;!TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=NACK:6DE60F283CD99033EEC6DF5DE044BE08F5151149E6DFD04FEA
0;255;3;0;9;Failed to transmit nonce!
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=2,c=3,t=16,pt=0,l=0,sg=0:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: 21D7B27EEF84BF6A8ABEA9264986E7637435C28952B4477F7AAAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;!TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=0,ft=0,st=NACK:21D7B27EEF84BF6A8ABEA9264986E7637435C28952B4477F7A
0;255;3;0;9;Failed to transmit nonce!
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=0,c=3,t=16,pt=0,l=0,sg=0:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: 3B83A566EB5C3E32546BE372D5913CB3FA8596A2F61DC57F1FAAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;!TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=0,ft=0,st=NACK:3B83A566EB5C3E32546BE372D5913CB3FA8596A2F61DC57F1F
0;255;3;0;9;Failed to transmit nonce!
0;255;3;0;9;TSF:MSG:READ,6-6-0,s=0,c=3,t=16,pt=0,l=0,sg=0:
0;255;3;0;9;Skipping security for command 3 type 16
0;255;3;0;9;SHA256: B6A6160EAF37C79EBCAEEE7701A6D798E2244CEB8B067A1FADAAAAAAAAAAAAAA
0;255;3;0;9;Skipping security for command 3 type 17
0;255;3;0;9;!TSF:MSG:SEND,0-0-6-6,s=255,c=3,t=17,pt=6,l=25,sg=0,ft=0,st=NACK:B6A6160EAF37C79EBCAEEE7701A6D798E2244CEB8B067A1FAD
0;255;3;0;9;Failed to transmit nonce!

RF issue?

Anticimex

@alexsh1 I think the problem is that you use the GW you reported was malfunctioning where the self test reported that the atsha204a did not answer as expected. And that you now try to use that device. Since the log said that a message failed to be signed.

alexsh1

@Anticimex No, the GW I am using is Mega 2560 with W5100 not the sensebender GW.
It has been working for many months after I resolved a power issue. However, signing is a different thing...

Anticimex

@alexsh1 seeing your latest log it appears you have rf issues. You have NACKs.

alexsh1

@Anticimex It seems that the legacy of nrf24l01+ RF communication is still chasing me ...
:((((((

Thank for your help

alexsh1

@Anticimex I did manage to make it after swapping a radio module:

Node log:

0 MCO:BGN:INIT NODE,CP=RNNNAA-,VER=2.1.1
4 TSM:INIT
4 TSF:WUR:MS=0
12 TSM:INIT:TSP OK
14 TSM:INIT:STATID=6
16 TSF:SID:OK,ID=6
18 TSM:FPAR
18 Will not sign message for destination 255 as it does not require it
61 TSF:MSG:SEND,6-6-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
245 TSF:MSG:READ,0-0-6,s=255,c=3,t=8,pt=1,l=1,sg=0:0
249 Skipping security for command 3 type 8
256 TSF:MSG:FPAR OK,ID=0,D=1
2070 TSM:FPAR:OK
2070 TSM:ID
2072 TSM:ID:OK
2074 TSM:UPL
2076 Skipping security for command 3 type 24
2082 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2101 TSF:MSG:READ,0-0-6,s=255,c=3,t=25,pt=1,l=1,sg=0:1
2107 Skipping security for command 3 type 25
2111 TSF:MSG:PONG RECV,HP=1
2115 TSM:UPL:OK
2117 TSM:READY:ID=6,PAR=0,DIS=1
2119 Signing required
2123 Skipping security for command 3 type 15
2129 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0101
2138 Waiting for GW to send signing preferences...
2166 TSF:MSG:READ,0-0-6,s=255,c=3,t=15,pt=6,l=2,sg=0:0101
2172 Skipping security for command 3 type 15
2179 Mark node 0 as one that require signed messages
2183 Mark node 0 as one that do not require whitelisting
2189 Skipping security for command 3 type 16
2195 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=OK:
2203 Nonce requested from 0. Waiting...
2207 Message to send could not be signed!
2211 !TSF:MSG:SIGN FAIL
2213 Skipping security for command 3 type 16
2222 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=1,st=OK:
2228 Nonce requested from 0. Waiting...
2232 Message to send could not be signed!
2236 !TSF:MSG:SIGN FAIL
2240 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:1BE362BF98C9E1F508502D7747DED1F8376FC361937F20CE6A
2250 Skipping security for command 3 type 17
2256 Nonce received from 0.
2258 Proceeding with signing...
Message to process: 06000E2306FF00
Current nonce: 1BE362BF98C9E1F508502D7747DED1F8376FC361937F20CE6AAAAAAAAAAAAAAA
HMAC: 3B9527A241A1BFB1A02E518D14912973BE3D259FC8A6CAFA402A677AEE279E20
Signature in message: 019527A241A1BFB1A02E518D14912973BE3D259FC8A6CAFA
2383 Message signed
2392 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:44401CD36C03AD558AA6503466C5DA2F01E5704FDB694FEC79
2402 Skipping security for command 3 type 17
2406 Nonce received from 0.
2410 Proceeding with signing...
Message to process: 06000E2306FF00
Current nonce: 44401CD36C03AD558AA6503466C5DA2F01E5704FDB694FEC79AAAAAAAAAAAAAA
HMAC: D0AE81996EB21C95474594FDB94C39A7632D3742FB4D7C2E75E765037BEE3041
Signature in message: 01AE81996EB21C95474594FDB94C39A7632D3742FB4D7C2E
2533 Message signed
4239 Skipping security for command 3 type 16
4245 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=1,st=OK:
4253 Nonce requested from 0. Waiting...
4284 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=1:E2261FE7028EC3025346CDB70233DAEB1371B5230AAD518FC3
4296 Skipping security for command 3 type 17
4300 Nonce received from 0.
4302 Proceeding with signing...
4306 Failed to sign message!
4308 Message to send could not be signed!
4313 !TSF:MSG:SIGN FAIL
4317 Skipping security for command 3 type 16
4323 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=1,st=OK:
4329 Nonce requested from 0. Waiting...
4362 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:A96C3564F5D0DFAF77FB11B256ED369DFBA6241F5089345413
4372 Skipping security for command 3 type 17
4376 Nonce received from 0.
4380 Proceeding with signing...
Message to process: 06001E030CFF312E31
Current nonce: A96C3564F5D0DFAF77FB11B256ED369DFBA6241F5089345413AAAAAAAAAAAAAA
HMAC: D39D3672372B7BD037D571D8D35F6F6322A7349F3148B40F286ACFA2805B82A2
Signature in message: 019D3672372B7BD037D571D8D35F6F6322A7349F3148
4505 Message signed
4513 Message to send has been signed
4519 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=12,pt=0,l=3,sg=1,ft=0,st=OK:1.1
4528 Skipping security for command 3 type 16
4534 TSF:MSG:SEND,6-6-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
4542 Nonce requested from 0. Waiting...
4663 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=1:F5DCC8A96132142030ACFDE7E7EFC75232D0F27E7CD5845D5D
4675 Skipping security for command 3 type 17
4679 Nonce received from 0.
4681 Proceeding with signing...
Message to process: 060006000800
Current nonce: F5DCC8A96132142030ACFDE7E7EFC75232D0F27E7CD5845D5DAAAAAAAAAAAAAA
HMAC: 9EB71F4EB9B6CF53A94E491367F3BD380C87FF26C413CFD4F2798C8F52BD7A3D
Signature in message: 01B71F4EB9B6CF53A94E491367F3BD380C87FF26C413CFD4F2
4806 Message signed
4814 Message to send has been signed
4820 TSF:MSG:SEND,6-6-0-0,s=0,c=0,t=8,pt=0,l=0,sg=1,ft=0,st=OK:
4829 Skipping security for command 3 type 16
4835 TSF:MSG:SEND,6-6-0-0,s=1,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
4843 Nonce requested from 0. Waiting...
4966 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=1:F310284FED0D6C8F5856B3CAD3460974122858DD71EDEFD8F8
4976 Skipping security for command 3 type 17
4980 Nonce received from 0.
4984 Proceeding with signing...
Message to process: 060006000601
Current nonce: F310284FED0D6C8F5856B3CAD3460974122858DD71EDEFD8F8AAAAAAAAAAAAAA
HMAC: 7C53D2D46131415C36657634AF69950186687C143509D199AD8DA3358CB0F636
Signature in message: 0153D2D46131415C36657634AF69950186687C143509D199AD
5107 Message signed
5115 Message to send has been signed
5122 TSF:MSG:SEND,6-6-0-0,s=1,c=0,t=6,pt=0,l=0,sg=1,ft=0,st=OK:
5128 Skipping security for command 3 type 16
5136 TSF:MSG:SEND,6-6-0-0,s=2,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
5144 Nonce requested from 0. Waiting...
5265 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=1:D8B7B2BAC0485BFF1AC6CFB2312B8ABD392E776AE29670ABF1
5277 Skipping security for command 3 type 17
5281 Nonce received from 0.
5283 Proceeding with signing...
Message to process: 060006000702
Current nonce: D8B7B2BAC0485BFF1AC6CFB2312B8ABD392E776AE29670ABF1AAAAAAAAAAAAAA
HMAC: FC0F44D95CCF58C065DFD54B4AD7A4222067560BB3957088E7FC1D4AF82E4FF8
Signature in message: 010F44D95CCF58C065DFD54B4AD7A4222067560BB3957088E7
5408 Message signed
5416 Message to send has been signed
5427 TSF:MSG:SEND,6-6-0-0,s=2,c=0,t=7,pt=0,l=0,sg=1,ft=0,st=OK:
5433 Skipping security for command 3 type 16
5441 TSF:MSG:SEND,6-6-0-0,s=3,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
5447 Nonce requested from 0. Waiting...
5568 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=1:01075582171E1B52EF26C04A9F6CD20BF2A4B690F430131644
5578 Skipping security for command 3 type 17
5584 Nonce received from 0.
5586 Proceeding with signing...
Message to process: 060006000D03
Current nonce: 01075582171E1B52EF26C04A9F6CD20BF2A4B690F430131644AAAAAAAAAAAAAA
HMAC: 15723FF6A4D539DE67CD75B2D42D7743012DAADD2282DF2C54633BB2A0426467
Signature in message: 01723FF6A4D539DE67CD75B2D42D7743012DAADD2282DF2C54
5711 Message signed
5720 Message to send has been signed
5726 TSF:MSG:SEND,6-6-0-0,s=3,c=0,t=13,pt=0,l=0,sg=1,ft=0,st=OK:
5732 MCO:REG:REQ
5734 Skipping security for command 3 type 26
5742 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=26,pt=1,l=1,sg=1,ft=0,st=OK:2
5851 TSF:MSG:READ,0-0-6,s=255,c=3,t=16,pt=0,l=0,sg=1:
5857 Skipping security for command 3 type 16
SHA256: 28366C70B76446E6C5DC055CC58108A110D2C824AB7F3F1B642845A9C0D087AE
5937 Skipping security for command 3 type 17
5949 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:28366C70B76446E6C5DC055CC58108A110D2C824AB7F3F1B64
5961 Transmitted nonce
6078 TSF:MSG:READ,0-0-6,s=255,c=3,t=27,pt=1,l=1,sg=1:1
Signature in message: 016CD1F0B409A5501C07F29F8D0CD5C1B7E39D86D679C9BB
Message to process: 00060E231BFF01
Current nonce: 28366C70B76446E6C5DC055CC58108A110D2C824AB7F3F1B64AAAAAAAAAAAAAA
HMAC: 1F6CD1F0B409A5501C07F29F8D0CD5C1B7E39D86D679C9BB62AA56E3DA35E996
6207 MCO:PIM:NODE REG=1
6213 MCO:BGN:STP
BME280 Pressure Sensor1.1isMetric: 1
6535 Skipping security for command 3 type 16
6543 TSF:MSG:SEND,6-6-0-0,s=3,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
6549 Nonce requested from 0. Waiting...
6580 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=1:F8B4C6C225F5F91BE58A32A2B45F8ACFA2D9BBC0C56DF1704E
6592 Skipping security for command 3 type 17
6596 Nonce received from 0.
6598 Proceeding with signing...
Message to process: 06002EE126033333534002
Current nonce: F8B4C6C225F5F91BE58A32A2B45F8ACFA2D9BBC0C56DF1704EAAAAAAAAAAAAAA
HMAC: 738C2FFDEAA1208BFA4FAA139FFEB6DD08D9A3DDE5575DC11A40A9CB7A892B49
Signature in message: 018C2FFDEAA1208BFA4FAA139FFEB6DD08D9A3DD
6721 Message signed
6729 Message to send has been signed
6735 TSF:MSG:SEND,6-6-0-0,s=3,c=1,t=38,pt=7,l=5,sg=1,ft=0,st=OK:3.30
6744 Skipping security for command 3 type 16
6754 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
6762 Nonce requested from 0. Waiting...
6881 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=1:1EF21E9C248C620832C15B2B31BFA59494E58B0025A12105C7
6891 Skipping security for command 3 type 17
6897 Nonce received from 0.
6899 Proceeding with signing...
Message to process: 06000E2300FF6B
Current nonce: 1EF21E9C248C620832C15B2B31BFA59494E58B0025A12105C7AAAAAAAAAAAAAA
HMAC: 2EA40330191EBC1C034C9B5FE86F15BB200C897E39C01A6A001387F54A7AC87E
Signature in message: 01A40330191EBC1C034C9B5FE86F15BB200C897E39C01A6A
7026 Message signed
7034 Message to send has been signed
7041 TSF:MSG:SEND,6-6-0-0,s=255,c=3,t=0,pt=1,l=1,sg=1,ft=0,st=OK:107
7049 MCO:BGN:INIT OK,TSP=1
Temperature = 25.59 *C
Humidity = 47.27 %
Pressure = 993.82 hPa
Forecast = unknown
7061 Skipping security for command 3 type 16
7071 TSF:MSG:SEND,6-6-0-0,s=1,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
7079 Nonce requested from 0. Waiting...
7084 Message to send could not be signed!
7088 !TSF:MSG:SIGN FAIL
7090 Skipping security for command 3 type 16
7096 TSF:MSG:SEND,6-6-0-0,s=2,c=3,t=16,pt=0,l=0,sg=0,ft=1,st=OK:
7104 Nonce requested from 0. Waiting...
7186 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=1:A534CA40967C4BF2319ECB1E9F78A46DAE29876C512FA43068
7196 Skipping security for command 3 type 17
7202 Nonce received from 0.
7204 Proceeding with signing...
Message to process: 0600160407E307FD
Current nonce: A534CA40967C4BF2319ECB1E9F78A46DAE29876C512FA43068AAAAAAAAAAAAAA
HMAC: DF63A40176DC348626CCF63EF31FDF9B381922BBA1035A00F48475B533B1FFB8
Signature in message: 0163A40176DC348626CCF63EF31FDF9B381922BBA1035A
7331 Message signed
7340 TSF:MSG:READ,0-0-6,s=255,c=3,t=17,pt=6,l=25,sg=0:CDABB60B9D503D264DE301FC0E70DBB3F14A5682D1D519643A
7352 Skipping security for command 3 type 17
7356 Nonce received from 0.
7358 Proceeding with signing...
Message to process: 0600160407E30802
Current nonce: CDABB60B9D503D264DE301FC0E70DBB3F14A5682D1D519643AAAAAAAAAAAAAAA
HMAC: B9D87BB4381C95DE3F87DB59BF7F8A3B78596AB1779ABD8A9D7000539D0FC9B3
Signature in message: 01D87BB4381C95DE3F87DB59BF7F8A3B78596AB1779ABD
7483 Message signed
7491 Message to send has been signed
7497 TSF:MSG:SEND,6-6-0-0,s=227,c=4,t=7,pt=0,l=2,sg=1,ft=0,st=OK:
7505 Skipping security for command 3 type 16
7512 TSF:MSG:SEND,6-6-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
7520 Nonce requested from 0. Waiting...
7524 Message to send could not be signed!
7528 !TSF:MSG:SIGN FAIL
7530 Skipping security for command 3 type 16
7536 TSF:MSG:SEND,6-6-0-0,s=0,c=3,t=16,pt=0,l=0,sg=0,ft=1,st=OK:
7544 Nonce requested from 0. Waiting...
7548 Message to send could not be signed!
7553 !TSF:MSG:SIGN FAIL
7606 MCO:SLP:MS=300000,SMS=0,I1=255,M1=255,I2=255,M2=255
7612 MCO:SLP:TPD

But it still throws many SIGN FAIL.

Anticimex

@alexsh1 the log still looks like you sometimes don't get the nonce you requested so signing times out and fails. I am still quite sure that if you looked in the log on the other side, it would show NACKs on some nonce transmissions. Signing won't work when those fail.

alexsh1

@Anticimex This is what we discussed before, this is not a signing issue. Guess what? I did notice that RF is much better with non-amplified nrf24l01+. Given my experience in the past with nrf24l01+ pa+lna, I have just soldered out and replaced AMS1117-3.3V (Mega 2560 works on 5V so I need a stable 3.3V source, which I cannot take from Mega's 3.3V pin for a hungry nrf24l01+pa+lna) and signing started working!

0 MCO:BGN:INIT NODE,CP=RNNNAS-,VER=2.1.1
4 TSM:INIT
4 TSF:WUR:MS=0
12 TSM:INIT:TSP OK
14 TSM:INIT:STATID=15
16 TSF:SID:OK,ID=15
18 TSM:FPAR
20 Will not sign message for destination 255 as it does not require it
63 TSF:MSG:SEND,15-15-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
1026 TSF:MSG:READ,0-0-15,s=255,c=3,t=8,pt=1,l=1,sg=0:0
1032 Skipping security for command 3 type 8
1038 TSF:MSG:FPAR OK,ID=0,D=1
2070 TSM:FPAR:OK
2070 TSM:ID
2072 TSM:ID:OK
2074 TSM:UPL
2076 Skipping security for command 3 type 24
2082 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2111 TSF:MSG:READ,0-0-15,s=255,c=3,t=25,pt=1,l=1,sg=0:1
2117 Skipping security for command 3 type 25
2121 TSF:MSG:PONG RECV,HP=1
2123 TSM:UPL:OK
2125 TSM:READY:ID=15,PAR=0,DIS=1
2129 Signing required
2131 Skipping security for command 3 type 15
2140 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0101
2148 Waiting for GW to send signing preferences...
2181 TSF:MSG:READ,0-0-15,s=255,c=3,t=15,pt=6,l=2,sg=0:0101
2187 Skipping security for command 3 type 15
2191 Mark node 0 as one that require signed messages
2197 Mark node 0 as one that do not require whitelisting
2203 Skipping security for command 3 type 16
2211 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=OK:
2220 Nonce requested from 0. Waiting...
2275 TSF:MSG:READ,0-0-15,s=255,c=3,t=17,pt=6,l=25,sg=0:BC9F06296E185623C02C586CECB3CBA37A7AD097699C918CB1
2287 Skipping security for command 3 type 17
2291 Nonce received from 0.
2295 Proceeding with signing...
Message to process: 0F002E0011FF322E312E31
Current nonce: BC9F06296E185623C02C586CECB3CBA37A7AD097699C918CB1AAAAAAAAAAAAAA
HMAC: D96C3B9964666D36495BBAF4E6C4E414088A553065E8CCA764CD8DF65D6353CA
Signature in message: 016C3B9964666D36495BBAF4E6C4E414088A5530
2469 Message signed
2478 Message to send has been signed
2486 TSF:MSG:SEND,15-15-0-0,s=255,c=0,t=17,pt=0,l=5,sg=1,ft=0,st=OK:2.1.1
2494 Skipping security for command 3 type 16
2502 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
2510 Nonce requested from 0. Waiting...
2643 TSF:MSG:READ,0-0-15,s=255,c=3,t=17,pt=6,l=25,sg=1:556C16AFC48CBCC8758A6D0BA0CA9920BAAFB13290AC599CC1
2656 Skipping security for command 3 type 17
2660 Nonce received from 0.
2662 Proceeding with signing...
Message to process: 0F000E2306FF00
Current nonce: 556C16AFC48CBCC8758A6D0BA0CA9920BAAFB13290AC599CC1AAAAAAAAAAAAAA
HMAC: 598965B2F76BF9805E79A23C9CDBEA71A5F0B5749D4E2FA44C3DEDDAD21B3238
Signature in message: 018965B2F76BF9805E79A23C9CDBEA71A5F0B5749D4E2FA4
2838 Message signed
2844 Message to send has been signed
2854 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=6,pt=1,l=1,sg=1,ft=0,st=OK:0
3801 TSF:MSG:READ,0-0-15,s=255,c=3,t=16,pt=0,l=0,sg=1:
3807 Skipping security for command 3 type 16
SHA256: 46DEE622257BDFA07B804BA9C02440CC083DC010C7A609123900000000000000
3842 Skipping security for command 3 type 17
3858 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:46DEE622257BDFA07B804BA9C02440CC083DC010C7A6091239
3870 Transmitted nonce
4012 TSF:MSG:READ,0-0-15,s=255,c=3,t=6,pt=0,l=1,sg=1:M
Signature in message: 018AF802A7325E4D37B322FA8B0F4BA61CA5DF6548CEE589
Message to process: 000F0E0306FF4D
Current nonce: 46DEE622257BDFA07B804BA9C02440CC083DC010C7A6091239AAAAAAAAAAAAAA
HMAC: DA8AF802A7325E4D37B322FA8B0F4BA61CA5DF6548CEE58953ADF17286D22669
4190 Skipping security for command 3 type 16
4202 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
4208 Nonce requested from 0. Waiting...
4255 TSF:MSG:READ,0-0-15,s=255,c=3,t=17,pt=6,l=25,sg=1:90818AAA44B6AFD7880153E7AA7E981981744CC98028809A09
4265 Skipping security for command 3 type 17
4272 Nonce received from 0.
4274 Proceeding with signing...
Message to process: 0F00B6030BFF424D503238302050726573737572652053656E736F72
Current nonce: 90818AAA44B6AFD7880153E7AA7E981981744CC98028809A09AAAAAAAAAAAAAA
HMAC: 486FAFD76801F66D900E883F2C012B7104EE043ABC68E0AE894D0026E9D7A8AB
Signature in message: 016FAF
4448 Message signed
4456 Message to send has been signed
4466 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=11,pt=0,l=22,sg=1,ft=0,st=OK:BMP280 Pressure Sensor
4476 Skipping security for command 3 type 16
4483 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
4491 Nonce requested from 0. Waiting...
4642 TSF:MSG:READ,0-0-15,s=255,c=3,t=17,pt=6,l=25,sg=1:A3B017C2562256E455C640C28667B9BB3D3062687A5C49160C
4655 Skipping security for command 3 type 17
4659 Nonce received from 0.
4661 Proceeding with signing...
Message to process: 0F001E030CFF312E31
Current nonce: A3B017C2562256E455C640C28667B9BB3D3062687A5C49160CAAAAAAAAAAAAAA
HMAC: F27274FF114AE80AE6217C1B2B80A322AB82697AF3BFBE59BC53069948AA234A
Signature in message: 017274FF114AE80AE6217C1B2B80A322AB82697AF3BF
4837 Message signed
4843 Message to send has been signed
4853 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=12,pt=0,l=3,sg=1,ft=0,st=OK:1.1
4861 Skipping security for command 3 type 16
4868 TSF:MSG:SEND,15-15-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
4876 Nonce requested from 0. Waiting...
9881 Timeout waiting for nonce!
9883 !TSF:MSG:SIGN FAIL
9885 Skipping security for command 3 type 16
9895 TSF:MSG:SEND,15-15-0-0,s=1,c=3,t=16,pt=0,l=0,sg=1,ft=1,st=OK:
9904 Nonce requested from 0. Waiting...
9957 TSF:MSG:READ,0-0-15,s=255,c=3,t=17,pt=6,l=25,sg=1:B91AB74E50528ACC3F64B480A47D6CEB269E2EA48004C57A7F
9967 Skipping security for command 3 type 17
9971 Nonce received from 0.
9975 Proceeding with signing...
Message to process: 0F0006000601
Current nonce: B91AB74E50528ACC3F64B480A47D6CEB269E2EA48004C57A7FAAAAAAAAAAAAAA
HMAC: A95DB25F392535043F3DEA960F6C2136115A29AF51F6B11D4E0BFFB7ABE9946E
Signature in message: 015DB25F392535043F3DEA960F6C2136115A29AF51F6B11D4E
10149 Message signed
10158 Message to send has been signed
10168 TSF:MSG:SEND,15-15-0-0,s=1,c=0,t=6,pt=0,l=0,sg=1,ft=0,st=OK:
10174 Skipping security for command 3 type 16
10182 TSF:MSG:SEND,15-15-0-0,s=2,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
10188 Nonce requested from 0. Waiting...
15194 Message to send could not be signed!
15198 !TSF:MSG:SIGN FAIL
15200 MCO:REG:REQ
15202 Skipping security for command 3 type 26
15212 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=26,pt=1,l=1,sg=1,ft=1,st=OK:2
15230 TSF:MSG:READ,0-0-15,s=255,c=3,t=16,pt=0,l=0,sg=1:
15237 Skipping security for command 3 type 16
SHA256: 6F1E9148E2B8755A2B5019D803BBE9E531F1B5507406B58820AAAAAAAAAAAAAA
15271 Skipping security for command 3 type 17
15286 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:6F1E9148E2B8755A2B5019D803BBE9E531F1B5507406B58820
15298 Transmitted nonce
15429 TSF:MSG:READ,0-0-15,s=255,c=3,t=27,pt=1,l=1,sg=1:1
Signature in message: 01B4B105F62283F53943B57B3B2B034B44DA23B4D71C97A1
Message to process: 000F0E231BFF01
Current nonce: 6F1E9148E2B8755A2B5019D803BBE9E531F1B5507406B58820AAAAAAAAAAAAAA
HMAC: B3B4B105F62283F53943B57B3B2B034B44DA23B4D71C97A14CE49895135B98FA
15607 MCO:PIM:NODE REG=1
15613 MCO:BGN:STP
Pressure Sensor BMP280 1.1
isMetric: 1
15628 Skipping security for command 3 type 16
15638 TSF:MSG:SEND,15-15-0-0,s=2,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
15646 Nonce requested from 0. Waiting...
15683 TSF:MSG:READ,0-0-15,s=255,c=3,t=17,pt=6,l=25,sg=1:4EDBAA807BB751EFD72E54A450E8B76C3B45D503270FF3C9C6
15693 Skipping security for command 3 type 17
15699 Nonce received from 0.
15702 Proceeding with signing...
Message to process: 0F002EE1260285EB514002
Current nonce: 4EDBAA807BB751EFD72E54A450E8B76C3B45D503270FF3C9C6AAAAAAAAAAAAAA
HMAC: 66D0E5314979BE6AC80387B12A6A8CF79AAB4C325F64A6762176D35C4E36C369
Signature in message: 01D0E5314979BE6AC80387B12A6A8CF79AAB4C32
15878 Message signed
15884 Message to send has been signed
15894 TSF:MSG:SEND,15-15-0-0,s=2,c=1,t=38,pt=7,l=5,sg=1,ft=0,st=OK:3.28
15902 Skipping security for command 3 type 16
15910 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
15919 Nonce requested from 0. Waiting...
16048 TSF:MSG:READ,0-0-15,s=255,c=3,t=17,pt=6,l=25,sg=1:7E290F0590861636DF52F69D21796856F958F03E7956953C8D
16060 Skipping security for command 3 type 17
16064 Nonce received from 0.
16068 Proceeding with signing...
Message to process: 0F000E2300FF69
Current nonce: 7E290F0590861636DF52F69D21796856F958F03E7956953C8DAAAAAAAAAAAAAA
HMAC: 164ABE25D777EE3EA65F536ADE147D60B404561D07A26CA156E25EBB234507E0
Signature in message: 014ABE25D777EE3EA65F536ADE147D60B404561D07A26CA1
16242 Message signed
16250 Message to send has been signed
16261 TSF:MSG:SEND,15-15-0-0,s=255,c=3,t=0,pt=1,l=1,sg=1,ft=0,st=OK:105
16269 MCO:BGN:INIT OK,TSP=1
Temperature = 24.96 *C
Pressure = 997.80 mBar
Forecast = unknown
16277 Skipping security for command 3 type 16
16287 TSF:MSG:SEND,15-15-0-0,s=1,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
16295 Nonce requested from 0. Waiting...
16410 TSF:MSG:READ,0-0-15,s=255,c=3,t=17,pt=6,l=25,sg=1:E4C3BDA88C3EFFD0A435849C1199E79C9D2B215FA1D05A7E76
16422 Skipping security for command 3 type 17
16427 Nonce received from 0.
16431 Proceeding with signing...
Message to process: 0F002EE1000114AEC74101
Current nonce: E4C3BDA88C3EFFD0A435849C1199E79C9D2B215FA1D05A7E76AAAAAAAAAAAAAA
HMAC: 144BFD3C6A7CBE0DC1CCEEC102FDA3E3A15C1A5A22BA604A5F5CAEE2F682BE37
Signature in message: 014BFD3C6A7CBE0DC1CCEEC102FDA3E3A15C1A5A
16605 Message signed
16613 Message to send has been signed
16623 TSF:MSG:SEND,15-15-0-0,s=1,c=1,t=0,pt=7,l=5,sg=1,ft=0,st=OK:25.0
16631 Skipping security for command 3 type 16
16637 TSF:MSG:SEND,15-15-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
16646 Nonce requested from 0. Waiting...
16766 TSF:MSG:READ,0-0-15,s=255,c=3,t=17,pt=6,l=25,sg=1:0E091DD4985125377E63651907B9830D4D7265831F17FD65FE
16779 Skipping security for command 3 type 17
16783 Nonce received from 0.
16787 Proceeding with signing...
Message to process: 0F002EE104002973794400
Current nonce: 0E091DD4985125377E63651907B9830D4D7265831F17FD65FEAAAAAAAAAAAAAA
HMAC: A157ECB56A03D70529E1F9A26D972AF3EB1332FB20E2A3CDD909D5A8B9F7A8C4
Signature in message: 0157ECB56A03D70529E1F9A26D972AF3EB1332FB
16961 Message signed
16969 Message to send has been signed
16975 TSF:MSG:SEND,15-15-0-0,s=0,c=1,t=4,pt=7,l=5,sg=1,ft=0,st=OK:998
16984 Skipping security for command 3 type 16
16992 TSF:MSG:SEND,15-15-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
16998 Nonce requested from 0. Waiting...
17129 TSF:MSG:READ,0-0-15,s=255,c=3,t=17,pt=6,l=25,sg=1:E7504291BD4FE363A66BD9A571064AFEB381F5282651DB1040
17141 Skipping security for command 3 type 17
17145 Nonce received from 0.
17149 Proceeding with signing...
Message to process: 0F003E010500756E6B6E6F776E
Current nonce: E7504291BD4FE363A66BD9A571064AFEB381F5282651DB1040AAAAAAAAAAAAAA
HMAC: 9E56ED49FE4589E4F61D7A954CF433334527DB1D8BC515183834201570327BF5
Signature in message: 0156ED49FE4589E4F61D7A954CF433334527
17324 Message signed
17332 Message to send has been signed
17342 TSF:MSG:SEND,15-15-0-0,s=0,c=1,t=5,pt=0,l=7,sg=1,ft=0,st=OK:unknown
17448 MCO:SLP:MS=300000,SMS=0,I1=255,M1=255,I2=255,M2=255
17455 MCO:SLP:TPD

This is the second time I change AMS1117 in one year. Very odd
Anyway, very much appreciate your help on signing! Very helpful

Anticimex

@alexsh1 glad you got it working again :)

alexsh1

@Anticimex Last time, I took me moths to resolve it. AMS1117 has not failed completely, but was working intermittently. This had a major impact on how nrf24l01+pa+lna was working. Unfortunately, range and signing were affected.
My theory is that it is getting probably 45-50C in my GW - there are many wires and it is a very tight fit. This may contribute in such AMS1117 behavior. Or probably just a bad batch.

Anticimex

@alexsh1 sounds like it. I've always considered the AMS1117 to be a trustworthy part.

alexsh1

@Anticimex it seems that replacing AMS1117 has resolved the issue.

I have a poor reception in one particular place and was thinking about a repeater node. Is signing working fine with the repeater node (both the node and the repeater are going to force signing by "MY_SIGNING_REQUEST_SIGNATURES"? Just curious

Anticimex

@alexsh1 repeaters support signing even if it isn't enabled on the repeater. It simply forwards the message and signature (and nonce).
Glad you resolved the issue :+1:

alexsh1

@Anticimex so no need to enable signing if this is just a repeater node? (No sleeping just waiting)

Yeah, every time it takes me quicker and quicker to troubleshoot mysensors ;-)
Obviously, thanks to your excellent support

Anticimex

@alexsh1 it never hurts to enable signing. It is not the same as requiring signatures. But no, you should not have to. I am just glad to help :)

[security] Introducing signing support to MySensors

14

11.7k

11.2k

113.0k