Mesh SDK: Unable to publish to nodes from interactive_pyaci without doing a reset

[Arif@Lynxemi]

Hi,

I have provisioned some nodes using interactive_pyaci successfully. Functionality is as expected. As a test, I then shut interactive_pyaci down, rebooted the nRF module and I can successfully re-add all the nodes from the database. Still able to publish and subscribe to the nodes. This exercise was to emulate a gateway going down and coming back up.

Then I exited, waiting over the weekend before coming back and doing the same test. This time, it doesn't work. On the nodes, I see this on RTT:

00> <t:    7089681>, net_packet.c,  228, Unencrypted data: : 0011EE00C401A86E455CA8B264AACA685665

In interactive_pyaci, no response is received:

In [72]: cc.composition_data_get()

>>>>>>>>>>>>>>>>>> OpCode: 0xab
>>>>>>>>>>>>>>>>>> Data: 0x0e 0xab 0x09 0x00 0x01 0x00 0x01 0x00 0x08 0x00 0x00 0x00 0x80 0x08 0x00

<<<<<<<<<<<<<<<<<<<<< Event name:  CmdRsp
<<<<<<<<<<<<<<<<<<<<< OpCode: 0x84
<<<<<<<<<<<<<<<<<<<<< Payload:  {'opcode': 171, 'status': 0, 'data': bytearray(b'1\x00\x00\x00')}
In [73]: <<<<<<<<<<<<<<<<<<<<< Data field: 0x31 0x00 0x00 0x00

2022-02-15 10:00:29,807 - INFO - ttyAMA0: PacketSend: {'token': 49}
<<<<<<<<<<<<<<<<<<<<< Event name:  MeshTxComplete
<<<<<<<<<<<<<<<<<<<<< OpCode: 0xd2
<<<<<<<<<<<<<<<<<<<<< Payload:  {'token': 49}

2022-02-15 10:00:29,860 - INFO - ttyAMA0: {event: MeshTxComplete, data: {'token': 49}}

This probably means that the messages are received by the mesh but are not accepted by the nodes. I tried a reset on the node I'm publishing to and finally I get the output I expected.

I am thinking the IV index may be outdated but is there any other reason for this issue? IIRC IV indexes shouldn't be out of range until well over 20 days.

P.S. I am aware that interactive_pyaci is not meant to be used in a production setting for a gateway. I am monitoring its protocols and creating my own production gateway software.

[Hung Bui]

Hi Muhammad, 

I agree that it sounds like IV Index and/or sequence number issue. 
Have you waited long enough (says 5-10 minutes) after turned on the gateway ? 

I'm checking internally with the mesh team if they have any idea. I will keep you updated. 

[Hung Bui]

Hi Muhammad, 

I got some feedback from the team. To be able to rule out the issue with IV Index or sequence number, we would suggest to do the following: 

To rule out the problem (or confirm it is the issue), it will great, if customer can print the IV index being used in PyACI, and also print the IV index being used on the nodes (by adding debug print here).

If it is an IV problem, customer can use "NetStateGet" to get the old SeqNumber and IV index, and then use the "NetStateSet" to set the new IV index (and subsequent SEQ number block). This should solve the IV issue.

[Arif@Lynxemi]

Hi,

I've carried out logging as your engineer has recommended. Here are the logs:

On the nodes:

00> <t:    6705511>, network.c,  313, <t:   13118908>, net_packet.c,  228, Unencrypted data: : 001000A998F4BDBB6884

It seems that it is not reaching the packet_send method in the first place but is receiving the unencrypted messages.

On the interactive_pyaci module:

00> <t:          0>, main.c,  211, ----- Bluetooth Mesh Serial Interface Application -----
00> <t:       9116>, main.c,  199, Initializing serial interface...
00> <t:       9120>, serial_handler_prov.c,  267, Generating encryption keypair...
00> <t:      13993>, nrf_mesh_serial.c,   80, Serial Device Init...
00> <t:      13997>, nrf_mesh_serial.c,   82, Serial Mesh Init...
00> <t:      14001>, nrf_mesh_serial.c,   84, Serial DFU Init...
00> <t:      14005>, main.c,  201, Done initializing serial interface...
00> <t:      14008>, main.c,  226, Initialization complete!
00> <t:      14012>, main.c,  231, Enabling serial interface...
00> <t:      14016>, mesh_app_utils.c,   66, Device UUID (raw): 5DB126A8D95F4D7A89D047D531BCBC26
00> <t:      14021>, mesh_app_utils.c,   67, Device UUID : 5DB126A8-D95F-4D7A-89D0-47D531BCBC26
00> <t:      14039>, main.c,  238, Bluetooth Mesh Serial Interface Application started!
00> <t:    1931675>, network.c,  312, IV Index: 0
00> <t:    1931678>, network.c,  313, Seq num: 0
00> <t:    2124489>, network.c,  312, IV Index: 0
00> <t:    2124492>, network.c,  313, Seq num: 1
00> <t:    2833957>, network.c,  312, IV Index: 0
00> <t:    2833961>, network.c,  313, Seq num: 2
00> <t:    3015344>, network.c,  312, IV Index: 0
00> <t:    3015347>, network.c,  313, Seq num: 3
00> <t:    3230553>, network.c,  312, IV Index: 0
00> <t:    3230556>, network.c,  313, Seq num: 4
00> <t:    3491807>, network.c,  312, IV Index: 0
00> <t:    3491810>, network.c,  313, Seq num: 5
00> <t:    3677322>, network.c,  312, IV Index: 0
00> <t:    3677325>, network.c,  313, Seq num: 6
00> <t:    3794876>, network.c,  312, IV Index: 0
00> <t:    3794879>, network.c,  313, Seq num: 7
00> <t:    4498817>, network.c,  312, IV Index: 0
00> <t:    4498821>, network.c,  313, Seq num: 8

I am running cc.composition_get() a few times and the packets are indeed being sent out.

These are the commands I am using to re-initialize my nodes:

db = MeshDB("database/example_database.json")
p = Provisioner(device, db)
device.send(cmd.DevkeyAdd(db.nodes[0].unicast_address, 0, db.nodes[0].device_key))
device.send(cmd.AddrPublicationAdd(db.nodes[0].unicast_address))
cc = ConfigurationClient(db)
device.model_add(cc)
cc.publish_set(8, 0)
cc.composition_data_get() // No response 

I printed the current IV index of the node and it still says 0. So maybe its a configuration problem I have made? But again doing a reset on the node solves it.

[Hung Bui]

Hi Muhammad, 
I suspect it's the sequence block issue. 
So for anti replay attack the receiver will ignore packet that comes from a node but have older sequence number than the last packet from the same node. 

Please do what the developer suggested, increase the sequence SEQ number block using NetStateSet. The sequence block to set is actually the sequence number (not the "block"). As long as it's bigger than the last sequence number used by the device it should be fine. 

I'm not sure sequence number 8 in your log is before or after the reset. But if you reset you need to set it to higher number. I would suggest to make a jump of 8192 (That's what we do in normal mesh node, where we jump NETWORK_SEQNUM_FLASH_BLOCK_SIZE after each reset) 

/**
* Number of sequence numbers between every write to flash. In case of power failure, the device
* will resume transmissions with the first sequence number in the next block. A larger block size
* means that the device can do fewer resets between every IV Update, while a smaller will result
* in a reduced lifetime for the flash hardware.
*/
#ifndef NETWORK_SEQNUM_FLASH_BLOCK_SIZE
#define NETWORK_SEQNUM_FLASH_BLOCK_SIZE 8192ul
#endif

[Arif@Lynxemi]

Hi,

I had to wait for this issue to crop up again before I could try your advice, so thank you for your patience. It works in general. After trying these commands, the network resumes where it left off:

In [13]: device.send(cmd.NetStateGet())

>>>>>>>>>>>>>>>>>> OpCode: 0xaf
>>>>>>>>>>>>>>>>>> Data: 0x01 0xaf

<<<<<<<<<<<<<<<<<<<<< Event name:  CmdRsp
<<<<<<<<<<<<<<<<<<<<< OpCode: 0x84
<<<<<<<<<<<<<<<<<<<<< Payload:  {'opcode': 175, 'status': 0, 'data': bytearray(b'\x00\x00\x00\x00\x00\x00\x00\x00 \x00\x00')}
<<<<<<<<<<<<<<<<<<<<< Data field: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x20 0x00 0x00

2022-03-14 05:28:04,814 - INFO - ttyAMA0: NetStateGet: {'iv_index': 0, 'iv_update_in_progress': 0, 'iv_update_timout_counter': 0, 'next_seqnum_block': 8192}
In [14]: device.send(cmd.NetStateSet(0, 0, 0, 8192))

>>>>>>>>>>>>>>>>>> OpCode: 0xae
>>>>>>>>>>>>>>>>>> Data: 0x0c 0xae 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x20 0x00 0x00

<<<<<<<<<<<<<<<<<<<<< Event name:  MeshIvEntrySetNotification
<<<<<<<<<<<<<<<<<<<<< OpCode: 0xd9
<<<<<<<<<<<<<<<<<<<<< Payload:  {'iv_index': 0, 'iv_update_in_progress': 0, 'iv_update_timeout_counter': 0}

2022-03-14 05:29:17,625 - INFO - ttyAMA0: {event: MeshIvEntrySetNotification, data: {'iv_index': 0, 'iv_update_in_progress': 0, 'iv_update_timeout_counter': 0}}
<<<<<<<<<<<<<<<<<<<<< Event name:  MeshIvUpdateNotification
<<<<<<<<<<<<<<<<<<<<< OpCode: 0xd3
<<<<<<<<<<<<<<<<<<<<< Payload:  {'iv_index': 0}

2022-03-14 05:29:17,656 - INFO - ttyAMA0: {event: MeshIvUpdateNotification, data: {'iv_index': 0}}
In [15]: <<<<<<<<<<<<<<<<<<<<< Event name:  MeshSeqnumEntrySetNotification
<<<<<<<<<<<<<<<<<<<<< OpCode: 0xda
<<<<<<<<<<<<<<<<<<<<< Payload:  {'next_block': 16384}

2022-03-14 05:29:17,694 - INFO - ttyAMA0: {event: MeshSeqnumEntrySetNotification, data: {'next_block': 16384}}
<<<<<<<<<<<<<<<<<<<<< Event name:  CmdRsp
<<<<<<<<<<<<<<<<<<<<< OpCode: 0x84
<<<<<<<<<<<<<<<<<<<<< Payload:  {'opcode': 174, 'status': 0, 'data': bytearray(b'')}

2022-03-14 05:29:17,735 - INFO - ttyAMA0: Success

One issue I find, is that I cannot issue NetStateSet command again without resetting the nrf module. Is this intended?

In [14]: device.send(cmd.NetStateSet(0, 0, 0, 16384))
>>>>>>>>>>>> Opcode: 0xae
>>>>>>>>>>>> Data: 0x0c 0xae 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x40 0x00

<<<<<<<<<<<< Event name: CmdRsp
<<<<<<<<<<<< OpCode: 0x84
<<<<<<<<<<<< Payload: {'opcode': 174, 'status': 131, 'data': bytearray(b'')}

2022-03-14 06:56:43,550 - ERROR - ttyAMA0: None: ERROR_INVALID_STATE