[SOLVED] MySigning cannot write hmac key to eeprom of standalone ATmega328p (sign verify fail)

alexanderkind

Hey everybody,

today I tried to use MySigning with a SerialGateway and a BinarySwitchSleepSensor but it didn't work.

The SerialGateway is an Arduino Nano and the sensor node is an ATmega328p@1Mhz on a Breadboard. The Nano is powered by USB and the ATmega is powered by battery (2 AA cells).

Arduino Nano SerialGateway:

#define MY_DEBUG

#define MY_RADIO_NRF24
#define MY_RF24_PA_LEVEL RF24_PA_MAX
#define MY_RF24_CHANNEL 71

#define MY_GATEWAY_SERIAL

#if F_CPU == 8000000L
#define MY_BAUD_RATE 115200
#endif

#define MY_DEFAULT_LED_BLINK_PERIOD 300

#define MY_SIGNING_SOFT
#define MY_SIGNING_REQUEST_SIGNATURES
#define MY_SIGNING_GW_REQUEST_SIGNATURES_FROM_ALL 
#include <MySensors.h>

void setup()
{
}

void presentation()
{
}

void loop()
{
}

ATmega node:

#define MY_NODE_ID 1

#define MY_DEBUG

#define MY_RADIO_NRF24
#define MY_RF24_PA_LEVEL RF24_PA_MAX
#define MY_RF24_CHANNEL 71

#define MY_SIGNING_SOFT
#define MY_SIGNING_REQUEST_SIGNATURES
#include <MySensors.h>
#include <Vcc.h>

#define PRIMARY_CHILD_ID 0

#define PRIMARY_BUTTON_PIN 3

int oldBatteryPcnt = 0;

const float VccMin   = 1.9;
const float VccMax   = 3.3;
// Measured Vcc by multimeter divided by reported Vcc
const float VccCorrection = 1.0 / 1.0;

Vcc vcc(VccCorrection);

MyMessage msg(PRIMARY_CHILD_ID, V_TRIPPED);

void setup()
{
  pinMode(PRIMARY_BUTTON_PIN, INPUT);

  digitalWrite(PRIMARY_BUTTON_PIN, HIGH);

  analogReference(INTERNAL);
}

void presentation()
{
  present(PRIMARY_CHILD_ID, S_DOOR);
}

void loop()
{
  uint8_t value;
  static uint8_t sentValue = 2;

  sleep(5);

  value = digitalRead(PRIMARY_BUTTON_PIN);

  if (value != sentValue) {
    send(msg.set(value == HIGH));
    sentValue = value;
  }

  int batteryPcnt = vcc.Read_Perc(VccMin, VccMax);
  if (oldBatteryPcnt != batteryPcnt) {
    sendBatteryLevel(batteryPcnt);
    oldBatteryPcnt = batteryPcnt;
  }

  sleep(PRIMARY_BUTTON_PIN - 2, CHANGE, 0);
}

I exactly followed these instructions and everything seemed to be fine. But there is no communication between the gateway and the node after the initial find parent request is answered by the gateway:

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
0;255;3;0;14;Gateway startup complete.
0;255;0;0;18;2.1.1
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,1-1-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=1
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;TSF:MSG:SEND,0-0-1-1,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=OK:0

If I remove the sleep instruction at the end of the node script I don't have this problem anymore but then I get a "sign verify fail" message.

I already checked the keys in the EEPROM with the SecurityPersonalizer.ino and they are still there. So nothing has overwritten the EEPROM.

If I completly remove the MySigning code everything just works fine:

0;255;3;0;9;MCO:BGN:INIT GW,CP=RNNGA--,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
0;255;3;0;14;Gateway startup complete.
0;255;0;0;18;2.1.1
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,1-1-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=1
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;TSF:MSG:SEND,0-0-1-1,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,1-1-0,s=255,c=3,t=24,pt=1,l=1,sg=0:1
0;255;3;0;9;TSF:MSG:PINGED,ID=1,HP=1
0;255;3;0;9;TSF:MSG:SEND,0-0-1-1,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,1-1-0,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
0;255;3;0;9;TSF:MSG:SEND,0-0-1-1,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
0;255;3;0;9;TSF:MSG:READ,1-1-0,s=255,c=0,t=17,pt=0,l=5,sg=0:2.1.1
1;255;0;0;17;2.1.1
0;255;3;0;9;TSF:MSG:READ,1-1-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0
1;255;3;0;6;0
0;255;3;0;9;TSF:MSG:READ,1-1-0,s=0,c=0,t=0,pt=0,l=0,sg=0:
1;0;0;0;0;
0;255;3;0;9;TSF:MSG:READ,1-1-0,s=255,c=3,t=26,pt=1,l=1,sg=0:2
0;255;3;0;9;TSF:MSG:SEND,0-0-1-1,s=255,c=3,t=27,pt=1,l=1,sg=0,ft=0,st=OK:1
0;255;3;0;9;TSF:MSG:READ,1-1-0,s=0,c=1,t=16,pt=1,l=1,sg=0:0
1;0;1;0;16;0
0;255;3;0;9;TSF:MSG:READ,1-1-0,s=255,c=3,t=0,pt=1,l=1,sg=0:69
1;255;3;0;0;69

I hope somebody can help me :+1:

Edit: Now the communication problem is solved but I still get the "sign verify fail" message. Debug output of the node:

0 MCO:BGN:INIT NODE,CP=RNNNAS-,VER=2.1.1
32 TSM:INIT
49 TSF:WUR:MS=0
81 TSM:INIT:TSP OK
98 TSM:INIT:STATID=1
131 TSF:SID:OK,ID=1
147 TSM:FPAR
196 TSF:MSG:SEND,1-1-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
1064 TSF:MSG:READ,0-0-1,s=255,c=3,t=8,pt=1,l=1,sg=1:0
1114 TSF:MSG:FPAR OK,ID=0,D=1
2293 TSM:FPAR:OK
2310 TSM:ID
2326 TSM:ID:OK
2342 TSM:UPL
2359 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2441 TSF:MSG:READ,0-0-1,s=255,c=3,t=25,pt=1,l=1,sg=1:1
2506 TSF:MSG:PONG RECV,HP=1
2539 TSM:UPL:OK
2555 TSM:READY:ID=1,PAR=0,DIS=1
2588 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0101
2686 TSF:MSG:READ,0-0-1,s=255,c=3,t=15,pt=6,l=2,sg=0:0101
2752 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=OK:
2834 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=0:EB2599F19FCF3F8046FFF401B88BA0A57A489EAB20B62AC91C
4227 TSF:MSG:SEND,1-1-0-0,s=255,c=0,t=17,pt=0,l=5,sg=1,ft=0,st=OK:2.1.1
4308 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
4390 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:12E9344AAEB6BF1A064AFD2E13081D1924A3D6B6758AD68595
5783 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=6,pt=1,l=1,sg=1,ft=0,st=OK:0
7880 TSF:MSG:SEND,1-1-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
7962 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:708B63BB7A30C43B18B20E73F8CEA18B2343238077ED5F341F
9355 TSF:MSG:SEND,1-1-0-0,s=0,c=0,t=0,pt=0,l=0,sg=1,ft=0,st=OK:
9420 MCO:REG:REQ
9453 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=26,pt=1,l=1,sg=1,ft=0,st=OK:2
9535 TSF:MSG:READ,0-0-1,s=255,c=3,t=16,pt=0,l=0,sg=1:
9830 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:EC89D0D3CE5C8BA3F0C559BEB77D7B1181D7D1BD753BD3AC6B
9961 TSF:MSG:READ,0-0-1,s=255,c=3,t=27,pt=1,l=1,sg=1:1
11288 !TSF:MSG:SIGN VERIFY FAIL
11337 MCO:BGN:STP
11354 MCO:BGN:INIT OK,TSP=1
11386 MCO:SLP:MS=5,SMS=0,I1=255,M1=255,I2=255,M2=255
11452 MCO:SLP:TPD
11468 MCO:SLP:WUP=-1
11501 TSF:MSG:SEND,1-1-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
11583 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:5B22EFBFFA514553827667BB7C406E63AB5216E72F520EF981
12976 TSF:MSG:SEND,1-1-0-0,s=0,c=1,t=16,pt=1,l=1,sg=1,ft=0,st=OK:0
13058 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
13139 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:C2269B73674B275848348F737A6CA5F932E886E678EE086AC9
14532 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=0,pt=1,l=1,sg=1,ft=0,st=OK:100
14614 MCO:SLP:MS=0,SMS=0,I1=1,M1=1,I2=255,M2=255
14680 MCO:SLP:TPD

Anticimex

@alexanderkind
Hi,
Can you please post the memory consumption report when you build the gateway sketch?
I suspect it crashes due to stack being too small.

alexanderkind

@Anticimex Do you mean this one?

Sketch uses 18868 bytes (61%) of program storage space. Maximum is 30720 bytes.
Global variables use 1182 bytes (57%) of dynamic memory, leaving 866 bytes for local variables. Maximum is 2048 bytes.

Anticimex

@alexanderkind yes. Does not look that bad. You could try with debugging disabled and see if it makes a difference. Apart from that, I don't really know what could be the issue, but the GW does not seem happy. The signing code has been verified though and should not be the cause of a crash in itself.

alexanderkind

@Anticimex Unfortunately it doesn't made a difference. Maybe someone else already had this problem...

Anticimex

@alexanderkind could you post the debug from the node? Perhaps the GW is still alive but the node isn't. Do you have other nodes running? I notice that you enabled the request from all flag on the gateway.

alexanderkind

@Anticimex Here it is:

0 MCO:BGN:INIT NODE,CP=RNNNAS-,VER=2.1.1
32 TSM:INIT
49 TSF:WUR:MS=0
81 TSM:INIT:TSP OK
98 TSM:INIT:STATID=1
131 TSF:SID:OK,ID=1
147 TSM:FPAR
196 TSF:MSG:SEND,1-1-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
1064 TSF:MSG:READ,0-0-1,s=255,c=3,t=8,pt=1,l=1,sg=1:0
1114 TSF:MSG:FPAR OK,ID=0,D=1
2293 TSM:FPAR:OK
2310 TSM:ID
2326 TSM:ID:OK
2342 TSM:UPL
2359 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2441 TSF:MSG:READ,0-0-1,s=255,c=3,t=25,pt=1,l=1,sg=1:1
2506 TSF:MSG:PONG RECV,HP=1
2539 TSM:UPL:OK
2555 TSM:READY:ID=1,PAR=0,DIS=1
2588 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0101
2686 TSF:MSG:READ,0-0-1,s=255,c=3,t=15,pt=6,l=2,sg=0:0101
2752 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=OK:
2834 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=0:EB2599F19FCF3F8046FFF401B88BA0A57A489EAB20B62AC91C
4227 TSF:MSG:SEND,1-1-0-0,s=255,c=0,t=17,pt=0,l=5,sg=1,ft=0,st=OK:2.1.1
4308 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
4390 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:12E9344AAEB6BF1A064AFD2E13081D1924A3D6B6758AD68595
5783 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=6,pt=1,l=1,sg=1,ft=0,st=OK:0
7880 TSF:MSG:SEND,1-1-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
7962 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:708B63BB7A30C43B18B20E73F8CEA18B2343238077ED5F341F
9355 TSF:MSG:SEND,1-1-0-0,s=0,c=0,t=0,pt=0,l=0,sg=1,ft=0,st=OK:
9420 MCO:REG:REQ
9453 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=26,pt=1,l=1,sg=1,ft=0,st=OK:2
9535 TSF:MSG:READ,0-0-1,s=255,c=3,t=16,pt=0,l=0,sg=1:
9830 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:EC89D0D3CE5C8BA3F0C559BEB77D7B1181D7D1BD753BD3AC6B
9961 TSF:MSG:READ,0-0-1,s=255,c=3,t=27,pt=1,l=1,sg=1:1
11288 !TSF:MSG:SIGN VERIFY FAIL
11337 MCO:BGN:STP
11354 MCO:BGN:INIT OK,TSP=1
11386 MCO:SLP:MS=5,SMS=0,I1=255,M1=255,I2=255,M2=255
11452 MCO:SLP:TPD
11468 MCO:SLP:WUP=-1
11501 TSF:MSG:SEND,1-1-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
11583 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:5B22EFBFFA514553827667BB7C406E63AB5216E72F520EF981
12976 TSF:MSG:SEND,1-1-0-0,s=0,c=1,t=16,pt=1,l=1,sg=1,ft=0,st=OK:0
13058 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
13139 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:C2269B73674B275848348F737A6CA5F932E886E678EE086AC9
14532 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=0,pt=1,l=1,sg=1,ft=0,st=OK:100
14614 MCO:SLP:MS=0,SMS=0,I1=1,M1=1,I2=255,M2=255
14680 MCO:SLP:TPD

The problem with the connection is gone. Now gateway and node are startig up correctly and are talking but I get the "sign verify fail" every time.

Anticimex

@alexanderkind could you enable the verbose signing debug flag on the node please?

alexanderkind

@Anticimex Yeah of course:

0 MCO:BGN:INIT NODE,CP=RNNNAS-,VER=2.1.1
32 TSM:INIT
49 TSF:WUR:MS=0
81 TSM:INIT:TSP OK
98 TSM:INIT:STATID=1
131 TSF:SID:OK,ID=1
147 TSM:FPAR
163 Will not sign message for destination 255 as it does not require it
278 TSF:MSG:SEND,1-1-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
2375 !TSM:FPAR:NO REPLY
2392 TSM:FPAR
2408 Will not sign message for destination 255 as it does not require it
2523 TSF:MSG:SEND,1-1-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
4636 !TSM:FPAR:NO REPLY
4653 TSM:FPAR
4669 Will not sign message for destination 255 as it does not require it
4800 TSF:MSG:SEND,1-1-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
6897 !TSM:FPAR:NO REPLY
6914 TSM:FPAR
6930 Will not sign message for destination 255 as it does not require it
7045 TSF:MSG:SEND,1-1-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
9158 !TSM:FPAR:FAIL
9175 TSM:FAIL:CNT=1
9191 TSM:FAIL:PDT

That's strange, isn't it? I will try it without the request from all flag on the gateway but I thought it would be right to set it if I want signing for all nodes. (At the moment I'm just experimenting with one node.)

alexanderkind

@Anticimex Sorry. It was my fault. Now it should be correct. Here is the new debug output:

0 MCO:BGN:INIT NODE,CP=RNNNAS-,VER=2.1.1
32 TSM:INIT
49 TSF:WUR:MS=0
81 TSM:INIT:TSP OK
98 TSM:INIT:STATID=1
131 TSF:SID:OK,ID=1
147 TSM:FPAR
163 Will not sign message for destination 255 as it does not require it
278 TSF:MSG:SEND,1-1-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
737 TSF:MSG:READ,0-0-1,s=255,c=3,t=8,pt=1,l=1,sg=1:0
802 Skipping security for command 3 type 8
851 TSF:MSG:FPAR OK,ID=0,D=1
2375 TSM:FPAR:OK
2392 TSM:ID
2408 TSM:ID:OK
2424 TSM:UPL
2441 Skipping security for command 3 type 24
2490 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2572 TSF:MSG:READ,0-0-1,s=255,c=3,t=25,pt=1,l=1,sg=1:1
2637 Skipping security for command 3 type 25
2686 TSF:MSG:PONG RECV,HP=1
2719 TSM:UPL:OK
2736 TSM:READY:ID=1,PAR=0,DIS=1
2768 Signing required
2801 Skipping security for command 3 type 15
2850 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0101
2932 Waiting for GW to send signing preferences...
2998 TSF:MSG:READ,0-0-1,s=255,c=3,t=15,pt=6,l=2,sg=0:0101
3063 Skipping security for command 3 type 15
3112 Mark node 0 as one that require signed messages
3162 Mark node 0 as one that do not require whitelisting
3227 Skipping security for command 3 type 16
3293 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=OK:
3358 Nonce requested from 0. Waiting...
3407 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=0:03AC0D8B3CB5CB15A89C1CA0D34A23A3CD126BB074F8B86363
3538 Skipping security for command 3 type 17
3588 Nonce received from 0.
3620 Proceeding with signing...
Message to process: 01002E0011FF322E312E31
Current nonce: 03AC0D8B3CB5CB15A89C1CA0D34A23A3CD126BB074F8B86363AAAAAAAAAAAAAA
HMAC: 42A3503DBB004E69A9D9F7D28B95840D053FC9392FA07DEEB0F7DF77FDE96F28
Signature in message: 01A3503DBB004E69A9D9F7D28B95840D053FC939
5062 Message signed
5160 Message to send has been signed
5193 TSF:MSG:SEND,1-1-0-0,s=255,c=0,t=17,pt=0,l=5,sg=1,ft=0,st=OK:2.1.1
5292 Skipping security for command 3 type 16
5341 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
5423 Nonce requested from 0. Waiting...
5472 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:4C7070935D33A92B30B5C969B2D73AD1528B7715B3DDBCE1A3
5586 Skipping security for command 3 type 17
5636 Nonce received from 0.
5668 Proceeding with signing...
Message to process: 01000E2306FF00
Current nonce: 4C7070935D33A92B30B5C969B2D73AD1528B7715B3DDBCE1A3AAAAAAAAAAAAAA
HMAC: CB7D06543C6086C9CCB25CF7DB42F0A81613215486A512EDA03238F8E33D3C4D
Signature in message: 017D06543C6086C9CCB25CF7DB42F0A81613215486A512ED
7127 Message signed
7208 Message to send has been signed
7258 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=6,pt=1,l=1,sg=1,ft=0,st=OK:0
9338 Skipping security for command 3 type 16
9388 TSF:MSG:SEND,1-1-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
9469 Nonce requested from 0. Waiting...
9502 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:39A8009337CE6B2429675B3EE9D1FD11A12CB201C27B7AB731
9633 Skipping security for command 3 type 17
9682 Nonce received from 0.
9715 Proceeding with signing...
Message to process: 010006000000
Current nonce: 39A8009337CE6B2429675B3EE9D1FD11A12CB201C27B7AB731AAAAAAAAAAAAAA
HMAC: 925B0FAED6941FFC943824E7ADBC694D1521C515B5C28BB0445873043CE2A167
Signature in message: 015B0FAED6941FFC943824E7ADBC694D1521C515B5C28BB044
11157 Message signed
11255 Message to send has been signed
11304 TSF:MSG:SEND,1-1-0-0,s=0,c=0,t=0,pt=0,l=0,sg=1,ft=0,st=OK:
11370 MCO:REG:REQ
11403 Skipping security for command 3 type 26
11452 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=26,pt=1,l=1,sg=1,ft=0,st=OK:2
11534 TSF:MSG:READ,0-0-1,s=255,c=3,t=16,pt=0,l=0,sg=1:
11599 Skipping security for command 3 type 16
SHA256: 21F723FE2BC6B783D6180A5D5FD4FA6FEEBC9619DB03AC42F700000000000000
11894 Skipping security for command 3 type 17
12009 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:21F723FE2BC6B783D6180A5D5FD4FA6FEEBC9619DB03AC42F7
12156 Transmitted nonce
12173 TSF:MSG:READ,0-0-1,s=255,c=3,t=27,pt=1,l=1,sg=1:1
Signature in message: 01F9F3C6AB0598E633E422941AED25C8326217E59EB80E2D
Message to process: 00010E231BFF01
Current nonce: 21F723FE2BC6B783D6180A5D5FD4FA6FEEBC9619DB03AC42F7AAAAAAAAAAAAAA
HMAC: 4DB8C02FBF9752C441D02C31E770CC7D7E9559C3F0323EB5E85949DB55479125
Signature bad: 01B8C02FBF9752C441D02C31E770CC7D7E9559C3F0323EB5
13729 Signature verification failed!
13828 !TSF:MSG:SIGN VERIFY FAIL
13860 MCO:BGN:STP
13893 MCO:BGN:INIT OK,TSP=1
13926 MCO:SLP:MS=5,SMS=0,I1=255,M1=255,I2=255,M2=255
13975 MCO:SLP:TPD
14008 MCO:SLP:WUP=-1
14024 Skipping security for command 3 type 16
14090 TSF:MSG:SEND,1-1-0-0,s=0,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
14155 Nonce requested from 0. Waiting...
14204 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:9C129D83097B589C208D1C9C33B1950DC9EE1C258CF7A93E05
14336 Skipping security for command 3 type 17
14385 Nonce received from 0.
14417 Proceeding with signing...
Message to process: 01000E21100000
Current nonce: 9C129D83097B589C208D1C9C33B1950DC9EE1C258CF7A93E05AAAAAAAAAAAAAA
HMAC: EB1086A4ED61967A799188580A94ED63AF3FA19D416CDFEBD44533337287719C
Signature in message: 011086A4ED61967A799188580A94ED63AF3FA19D416CDFEB
15876 Message signed
15958 Message to send has been signed
16007 TSF:MSG:SEND,1-1-0-0,s=0,c=1,t=16,pt=1,l=1,sg=1,ft=0,st=OK:0
16089 Skipping security for command 3 type 16
16138 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
16220 Nonce requested from 0. Waiting...
16269 TSF:MSG:READ,0-0-1,s=255,c=3,t=17,pt=6,l=25,sg=1:387EA66DC5039E8E6868373832492E019E1A5A055A01A69988
16400 Skipping security for command 3 type 17
16449 Nonce received from 0.
16482 Proceeding with signing...
Message to process: 01000E2300FF64
Current nonce: 387EA66DC5039E8E6868373832492E019E1A5A055A01A69988AAAAAAAAAAAAAA
HMAC: 33644999A7B56076EBC8E6C12C787406C9348F721D1B7AEC56F5430DC1A659CD
Signature in message: 01644999A7B56076EBC8E6C12C787406C9348F721D1B7AEC
17924 Message signed
18022 Message to send has been signed
18071 TSF:MSG:SEND,1-1-0-0,s=255,c=3,t=0,pt=1,l=1,sg=1,ft=0,st=OK:100
18153 MCO:SLP:MS=0,SMS=0,I1=1,M1=1,I2=255,M2=255
18202 MCO:SLP:TPD

Anticimex

@alexanderkind from your last log, I don't see the signing presentation data being exchanged so the node have not yet learned of the gw:s signing preferences.

Anticimex

@alexanderkind ok, everything points to that the GW and the node have different hmac keys. Are you absolutely positive that they are identical?
You don't need to post them as proof, just make sure that every single bit is the same :)
The security personalizer can be configured to dump them. Or you can dump eeprom by other means.

alexanderkind

@Anticimex I will try to dump them with the security personalizer. I already did that earlier. Should be no problem. But I thought they were the same :confused:

alexanderkind

@Anticimex You're definitely right. For some reason I can't write the key to the eeprom of the ATmega328p. If I upload the sketch and then try to dump the keys, there are only many F's. With the Arduino Nano Gateway everything works fine.

You're great! I would have never thought that it could be such a problem :) But now I have to solve that :joy:

Anticimex

@alexanderkind well, sorry to hear that you have a problem with the eeprom. Glad to be able to help out in troubleshooting it.
Perhaps you have some code on your node that writes to eeprom and happens to write to the wrong place? (only speculating). But now at least you have a reason for the the failed verifications. 👍

alexanderkind

@Anticimex I think I will try that tomorrow. And I will set up the node with another Arduino Nano instead of the ATmega standalone to see if that works :+1:

alexanderkind

@Anticimex I couldn't stop trying to fix the problem :) Now it's working. I had to set different fuses with avrdude because EESAVE wasn't enabled. So every upload with the Arduino IDE cleaned the eeprom :)

Anticimex

@alexanderkind great that the root cause was found! And now we have a forum thread for others to read in case they have the same problem! Thanks for reporting!

[SOLVED] MySigning cannot write hmac key to eeprom of standalone ATmega328p (sign verify fail)

11

11.7k

11.2k

113.1k