Android-nRF-Mesh-Library
Android-nRF-Mesh-Library copied to clipboard
Published
20 hours ago •
NordicSemiconductor
NordicSemiconductor
Problem with IV index udpate
Hi, I did some test with IV index using nRF Mesh, here the steps:
- provisioned 2 devices in a new mesh (device that have nordic SDK, IV test flag enabled)
- from one devices, I triggered the IV index update from 0 to 1
- after the finish of the IV procedure, I tried to interact with devices using nRF Mesh -> OK (get/set status, bind app key etc)
- from the same device of point 2, I triggered the IV index update again, from 1 to 2
- after the finish of the IV procedure, I tried to interact with devices using nRF Mesh -> FAIL (can't get/set status, can't bind app key etc)
- I also tried to add a third device into the same mesh -> provisioning ok but every next operation fails (can't bind app key, get/set status is not possibile due to missing app key binding)
It seems that when mesh IV is over 1 nRF mesh can't interact with it because app still use IV 0 while the devices use IV 2.
I tried the steps above using:
- Android nRF Mesh v3.2.4
- iOS nRF Mesh v3.2.0
Hi Philips, of course, I did all the steps described above with and without IV Test Mode flag enabled. I run all the steps again today just to be sure.
Hi, sorry for late reply. Do you have that issue on both Android and iOS? Our apps are getting the IV index from Secure Network Beacons. Try disconnecting the phone after each IV update, do that the phone could get the current version. It should be sent over GATT, but perhaps it's not. But for sure it will be when you reconnect to a proxy node.
Let me be more clear here.
During an IV Update procedure, the Proxy Node should rely Secure Network Beacons with updated IV state to the phone. However, seems like that is not the case. As SNBs are sent over ADV bearer regularly, all the other nodes get the current IV Index state almost immediately, but the Proxy Node filters them out and only sends them on new connection and when IV changes. Could you check if you get it retransmitted from the Proxy over GATT bearer? If not, after each phase transition in IV Index update disconnect and reconnect the phone so it gets the SNB on reconnection.
Hi Philips, I have the issue on both, Android and iOS.
Can you please explain how to check if the SNB is retransmitted? BTW I checked and, after a reconnect, app still can't communicate with provisioned devices.
Sure. Whenever a Proxy Node participates in IV Index update it should send new updated IV Index using SNB over GATT to connected client. If the IV Index update isn't originating from the Proxy Node, make sure its IV Index Test Mode is also enabled, or it will ignore the update before passing to GATT.
The easiest setup consists of a Proxy Node, on which you initiate the change, and a phone with nRF Mesh connected to it.
Make sure you enable IV Index Test Mode in the app and on the Proxy. All nodes used for the test should have it enabled.
After each IV Index update the phone should get a SNB, which should be accepted (check logs on the phone, either using LogCat, or Console app on connected Mac).
Mind, that IV Index Test Mode only removes the restriction for a single update (one step). It can't update from IV = 0 to 2 without waiting 196h unless IV = 1 is also received in the middle.
Steps to test:
- On a new brown provision a node.
- Enable IV Index Test Mode in both the phone and the node.
- Make sure the phone is connected to the node.
- Trigger IV Index update from the node to IV=0, mode=active.
- A SNB should be received in the phone:
- You should be about to send messages.
- Trigger IV Index update again. This time it will be IV=1, mode=normal.
- Verify that the SNB was received and handled, repeat sending and receiving messages to test.
- Trigger update again, to IV=1, mode=active.
- Repeat testing.
- ...
Make sure the SNB was received in each step. If not, the following will be rejected it required time hasn't passed:
Hi Philips,
I ran your steps without being able to get info from the devices in the end (Android).
IV index is 2 and in normal operation.
I tried a reconnect:
Please, can you tell me how to better filter log obtained with iOS Console?
On Android, from terminal, I used the following:
adb logcat --pid=$(adb shell pidof -s no.nordicsemi.android.nrfmeshprovisioner)
I ran your steps without being able to get info from the devices in the end (Android). IV index is 2 and in normal operation.
Again, so is it working, or not? What would you expect instead?
Looks like in both listings you're getting a valid SMB with IV = 2 (normal operation).
In the Console app you may filter by SUBSYSTEM: com.nordicsemi.nRFProvisioner
Hello again
I ran a lot of tests in the last few days following your indications.
iOS app
iOS nRF Mesh seems to work almost fine, I was able to reach IV 4 and still was able to read/set a GenericOnOff state from the device. However, I think there is an issue: when stepping to the next IV the app gets the SNB indicating each step (first the SNB indicating IV n+1 and active state and later the SNB indicating IV n+1 with normal operation) but can't send messages until a disconnect+reconnect to the proxy GATT. I get the same issue when provisioning a new node: the new node gets provisioned with the correct IV (for example IV 4) but then the app can't get the composition data until a disconnect+reconnect. Step to reproduce are:
- provision a few nodes (with the IV test flag enable of course)
- step the IV index (until 4 for example) from the nodes
- power off the nodes already provisioned
- provision a new node -> the app will correctly provision with IV 4 but then can't get the composition data until a disconnect+reconnect to the proxy GATT
Here I gathered a bunch of logs retrivied while testing with IV updates with iOS
GenericOnOffServer get of a node -> OK
11:32:44.327605 Sending GenericOnOffGet() from: Primary Element (0x0001), to: 0006
11:32:44.327764 Sending Access PDU (opcode: 0x8201, parameters: 0x)
11:32:44.332606 Sending Upper Transport PDU (encrypted data: 0x5CB5, transMic: 0xCF676216) encrypted using key: App Key 1 (index: 0)
11:32:44.332969 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0x5CB5CF676216)
11:32:44.334290 Sending Network PDU (ivi: 0, nid: 0x62, ctl: 0, ttl: 5, seq: 36, src: 0001, dst: 0006, transportPdu: 0x4DA00D95D8BFB6, netMic: 0x1FAEEC0D) encrypted using Primary Network Key (index: 0)
11:32:44.334923 -> 0x0062A0A07AF4A489DC534DA00D95D8BFB61FAEEC0D
11:32:44.689084 <- 0x00628D419C72D8CDDD6F65F05DBAB5954A053CFB844BBBA77D
11:32:44.690429 Network PDU (ivi: 0, nid: 0x62, ctl: 0, ttl: 3, seq: 17, src: 0006, dst: 0001, transportPdu: 0x65F05DBAB5954A053CFB84, netMic: 0x4BBBA77D) received
11:32:44.694252 Segmented Access Message (akf: 1, aid: 0x2B, szmic: 0, seqZero: 17, segO: 0, segN: 0, data: 0x71BE6EC73E1B37) received (decrypted using key: Primary Network Key (index: 0))
11:32:44.694333 Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0x71BE6EC73E1B37) received
11:32:44.694643 Upper Transport PDU (encrypted data: 0x71BE6E, transMic: 0xC73E1B37) received
11:32:44.694710 Sending ACK (seqZero: 17, blockAck: 0x00000001)
11:32:44.694775 Response Access PDU (opcode: 0x8204, parameters: 0x00) received (decrypted using key: App Key 1 (index: 0))
11:32:44.695172 GenericOnOffStatus(isOn: false, targetState: nil, remainingTime: nil) received from: 0006, to: 0001
11:32:44.695259 Local Generic OnOff Client model on Primary Element (0x0001) not bound to key: App Key 1 (index: 0)
11:32:44.695393 GenericOnOffStatus(isOn: false, targetState: nil, remainingTime: nil) already decoded as GenericOnOffStatus(isOn: false, targetState: nil, remainingTime: nil)
11:32:44.696822 Sending Network PDU (ivi: 0, nid: 0x62, ctl: 1, ttl: 5, seq: 37, src: 0001, dst: 0006, transportPdu: 0xEDDAF1977C1583, netMic: 0x2DF580A907DB5C19) encrypted using Primary Network Key (index: 0)
11:32:44.696923 -> 0x00628B9DB0CF88A54034EDDAF1977C15832DF580A907DB5C19
GenericOnOffServer set of a node -> OK
11:33:18.944694 Sending GenericOnOffSetUnacknowledged(tid: Optional(147), isOn: true, transitionTime: nil, delay: nil) from: Primary Element (0x0001), to: 0006
11:33:18.944761 Sending Access PDU (opcode: 0x8203, parameters: 0x0193)
11:33:18.946157 Sending Upper Transport PDU (encrypted data: 0xCFFC4DAE, transMic: 0x84139A9B) encrypted using key: App Key 1 (index: 0)
11:33:18.946350 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0xCFFC4DAE84139A9B)
11:33:18.954992 Sending Network PDU (ivi: 0, nid: 0x62, ctl: 0, ttl: 5, seq: 38, src: 0001, dst: 0006, transportPdu: 0xC2E3719D8130F5423D, netMic: 0xE6ECD1DC) encrypted using Primary Network Key (index: 0)
11:33:18.955888 -> 0x0062E56C5080DC5F0657C2E3719D8130F5423DE6ECD1DC
_After enabling IV test flag in app and triggering a IV update_
SNB saying IV 1, update active
11:34:06.948585 <- 0x010102852FAECB44FDB19800000001AE85B7169CEED36C
11:34:06.969903 Secure Network beacon (Network ID: 852FAECB44FDB198, IV Index: 1 (update active), Key Refresh Flag: false) received (decrypted using key: Primary Network Key (index: 0))
11:34:06.971029 Applying IV Index: 1 (update active)
SNB saying IV 1, normal operation
11:35:13.369957 <- 0x010100852FAECB44FDB198000000012D518E79805ADC59
11:35:13.374475 Secure Network beacon (Network ID: 852FAECB44FDB198, IV Index: 1 (normal operation), Key Refresh Flag: false) received (decrypted using key: Primary Network Key (index: 0))
11:35:13.390774 Applying IV Index: 1 (normal operation)
11:35:13.390928 Resetting local sequence numbers to 0
GenericOnOffServer get of a node with IV 1 -> OK
11:35:55.850630 Sending GenericOnOffGet() from: Primary Element (0x0001), to: 0006
11:35:55.850697 Sending Access PDU (opcode: 0x8201, parameters: 0x)
11:35:55.853368 Sending Upper Transport PDU (encrypted data: 0x4E32, transMic: 0xB61F96EC) encrypted using key: App Key 1 (index: 0)
11:35:55.853455 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0x4E32B61F96EC)
11:35:55.853840 Sending Network PDU (ivi: 1, nid: 0x62, ctl: 0, ttl: 5, seq: 0, src: 0001, dst: 0006, transportPdu: 0x978E34E7476693, netMic: 0xA57B93C1) encrypted using Primary Network Key (index: 0)
11:35:55.854126 -> 0x00E2BC15989F0D3C52CD978E34E7476693A57B93C1
11:35:57.649863 <- 0x00E2364B6AC91BFD2F54583D3183B08AAF230B6CC775093FDD
11:35:57.651113 Network PDU (ivi: 1, nid: 0x62, ctl: 0, ttl: 3, seq: 2, src: 0006, dst: 0001, transportPdu: 0x583D3183B08AAF230B6CC7, netMic: 0x75093FDD) received
11:35:57.656711 Segmented Access Message (akf: 1, aid: 0x2B, szmic: 0, seqZero: 0, segO: 0, segN: 0, data: 0x2F7EB2DD5DBB0F) received (decrypted using key: Primary Network Key (index: 0))
11:35:57.656863 Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0x2F7EB2DD5DBB0F) received
11:35:57.657443 Sending ACK (seqZero: 0, blockAck: 0x00000001)
11:35:57.657728 Upper Transport PDU (encrypted data: 0x2F7EB2, transMic: 0xDD5DBB0F) received
11:35:57.658471 Response Access PDU (opcode: 0x8204, parameters: 0x01) received (decrypted using key: App Key 1 (index: 0))
11:35:57.658843 GenericOnOffStatus(isOn: true, targetState: nil, remainingTime: nil) received from: 0006, to: 0001
11:35:57.659233 Local Generic OnOff Client model on Primary Element (0x0001) not bound to key: App Key 1 (index: 0)
11:35:57.659655 GenericOnOffStatus(isOn: true, targetState: nil, remainingTime: nil) already decoded as GenericOnOffStatus(isOn: true, targetState: nil, remainingTime: nil)
11:35:57.661886 Sending Network PDU (ivi: 1, nid: 0x62, ctl: 1, ttl: 5, seq: 1, src: 0001, dst: 0006, transportPdu: 0xDB84CD3AACC1DF, netMic: 0x0A45D38DF2E98EF4) encrypted using Primary Network Key (index: 0)
11:35:57.662214 -> 0x00E2BED5E3B0FD6A2419DB84CD3AACC1DF0A45D38DF2E98EF4
_Triggering a new IV update_
SNB saying IV 2, update active
11:38:13.732561 <- 0x010102852FAECB44FDB19800000002B005455834C412CF
11:38:13.755126 Secure Network beacon (Network ID: 852FAECB44FDB198, IV Index: 2 (update active), Key Refresh Flag: false) received (decrypted using key: Primary Network Key (index: 0))
11:38:13.756776 Applying IV Index: 2 (update active)
SNB saying IV 2, normal operation
11:39:33.292548 <- 0x010100852FAECB44FDB19800000002697F87306248332B
11:39:33.299751 Secure Network beacon (Network ID: 852FAECB44FDB198, IV Index: 2 (normal operation), Key Refresh Flag: false) received (decrypted using key: Primary Network Key (index: 0))
11:39:33.311955 Applying IV Index: 2 (normal operation)
11:39:33.312031 Resetting local sequence numbers to 0
GenericOnOffServer get of a node with IV 2 -> OK (with some retries)
11:42:39.832159 Sending GenericOnOffGet() from: Primary Element (0x0001), to: 0006
11:42:39.832278 Sending Access PDU (opcode: 0x8201, parameters: 0x)
11:42:39.834815 Sending Upper Transport PDU (encrypted data: 0xC830, transMic: 0x69194221) encrypted using key: App Key 1 (index: 0)
11:42:39.834887 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0xC83069194221)
11:42:39.835553 Sending Network PDU (ivi: 0, nid: 0x62, ctl: 0, ttl: 5, seq: 0, src: 0001, dst: 0006, transportPdu: 0xCC7131064D8846, netMic: 0x102CEE0A) encrypted using Primary Network Key (index: 0)
11:42:39.835675 -> 0x00623C587AE1F1BF61ADCC7131064D8846102CEE0A
11:42:44.420263 Resending Access PDU (opcode: 0x8201, parameters: 0x)
11:42:44.424721 Sending Upper Transport PDU (encrypted data: 0x810F, transMic: 0x1DA7768A) encrypted using key: App Key 1 (index: 0)
11:42:44.424869 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0x810F1DA7768A)
11:42:44.425695 Sending Network PDU (ivi: 0, nid: 0x62, ctl: 0, ttl: 5, seq: 1, src: 0001, dst: 0006, transportPdu: 0xF7A3B8542DAE0C, netMic: 0x1F4A6A70) encrypted using Primary Network Key (index: 0)
11:42:44.425954 -> 0x006227548E816A57FBBBF7A3B8542DAE0C1F4A6A70
11:42:53.494834 Resending Access PDU (opcode: 0x8201, parameters: 0x)
11:42:53.499605 Sending Upper Transport PDU (encrypted data: 0x44DE, transMic: 0x3F83BECB) encrypted using key: App Key 1 (index: 0)
11:42:53.499752 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0x44DE3F83BECB)
11:42:53.500586 Sending Network PDU (ivi: 0, nid: 0x62, ctl: 0, ttl: 5, seq: 2, src: 0001, dst: 0006, transportPdu: 0x16C131A97AA820, netMic: 0x85BF0133) encrypted using Primary Network Key (index: 0)
11:42:53.500869 -> 0x0062C75AA9C3687607CB16C131A97AA82085BF0133
11:43:11.577225 Resending Access PDU (opcode: 0x8201, parameters: 0x)
11:43:11.581706 Sending Upper Transport PDU (encrypted data: 0xCE25, transMic: 0x220E0F44) encrypted using key: App Key 1 (index: 0)
11:43:11.581857 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0xCE25220E0F44)
11:43:11.582794 Sending Network PDU (ivi: 0, nid: 0x62, ctl: 0, ttl: 5, seq: 3, src: 0001, dst: 0006, transportPdu: 0xF66A702DE7F3CD, netMic: 0x652DEA26) encrypted using Primary Network Key (index: 0)
11:43:11.583045 -> 0x0062125DA59DC30963D1F66A702DE7F3CD652DEA26
11:43:13.975028 <- 0x0062D2802976E9E90B9DB6D24A528049CE12E05BA8E27C6E00
11:43:13.976283 Network PDU (ivi: 0, nid: 0x62, ctl: 0, ttl: 2, seq: 8, src: 0006, dst: 0001, transportPdu: 0xB6D24A528049CE12E05BA8, netMic: 0xE27C6E00) received
11:43:13.982373 Segmented Access Message (akf: 1, aid: 0x2B, szmic: 0, seqZero: 5, segO: 0, segN: 0, data: 0xDB965EB1D3D3E0) received (decrypted using key: Primary Network Key (index: 0))
11:43:13.982630 Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0xDB965EB1D3D3E0) received
11:43:13.983149 Sending ACK (seqZero: 5, blockAck: 0x00000001)
11:43:13.983422 Upper Transport PDU (encrypted data: 0xDB965E, transMic: 0xB1D3D3E0) received
11:43:13.984168 Response Access PDU (opcode: 0x8204, parameters: 0x01) received (decrypted using key: App Key 1 (index: 0))
11:43:13.984539 GenericOnOffStatus(isOn: true, targetState: nil, remainingTime: nil) received from: 0006, to: 0001
11:43:13.984883 Local Generic OnOff Client model on Primary Element (0x0001) not bound to key: App Key 1 (index: 0)
11:43:13.985274 GenericOnOffStatus(isOn: true, targetState: nil, remainingTime: nil) already decoded as GenericOnOffStatus(isOn: true, targetState: nil, remainingTime: nil)
11:43:13.988218 Sending Network PDU (ivi: 0, nid: 0x62, ctl: 1, ttl: 5, seq: 4, src: 0001, dst: 0006, transportPdu: 0x35C108D047453E, netMic: 0x54960B7A630796EC) encrypted using Primary Network Key (index: 0)
11:43:13.996412 -> 0x0062935B985F1CC675D735C108D047453E54960B7A630796EC
_Triggering a new IV update_
SNB saying IV 3, update active
11:46:33.239151 <- 0x010102852FAECB44FDB19800000003ACC7D691A5F950F8
11:46:33.256949 Secure Network beacon (Network ID: 852FAECB44FDB198, IV Index: 3 (update active), Key Refresh Flag: false) received (decrypted using key: Primary Network Key (index: 0))
11:46:33.257853 Applying IV Index: 3 (update active)
SNB saying IV , normal operation
11:47:53.700551 <- 0x010100852FAECB44FDB198000000037903FE82CD081F62
11:47:53.703087 Secure Network beacon (Network ID: 852FAECB44FDB198, IV Index: 3 (normal operation), Key Refresh Flag: false) received (decrypted using key: Primary Network Key (index: 0))
11:47:53.717777 Applying IV Index: 3 (normal operation)
11:47:53.717832 Resetting local sequence numbers to 0
GenericOnOffServer get of a node with IV 3 -> FAIL (timeout)
11:48:14.475922 Sending GenericOnOffGet() from: Primary Element (0x0001), to: 0006
11:48:14.476332 Sending Access PDU (opcode: 0x8201, parameters: 0x)
11:48:14.480338 Sending Upper Transport PDU (encrypted data: 0xA660, transMic: 0x3F3D9F45) encrypted using key: App Key 1 (index: 0)
11:48:14.480415 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0xA6603F3D9F45)
11:48:14.480909 Sending Network PDU (ivi: 1, nid: 0x62, ctl: 0, ttl: 5, seq: 0, src: 0001, dst: 0006, transportPdu: 0xBF77AADF38DC5D, netMic: 0x7F6ABE1B) encrypted using Primary Network Key (index: 0)
11:48:14.481097 -> 0x00E2A3070E6E595B0640BF77AADF38DC5D7F6ABE1B
11:48:19.083873 Resending Access PDU (opcode: 0x8201, parameters: 0x)
11:48:19.084242 Sending Upper Transport PDU (encrypted data: 0xB1A7, transMic: 0xD8FA843E) encrypted using key: App Key 1 (index: 0)
11:48:19.084321 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0xB1A7D8FA843E)
11:48:19.084389 Sending Network PDU (ivi: 1, nid: 0x62, ctl: 0, ttl: 5, seq: 1, src: 0001, dst: 0006, transportPdu: 0x8D1E0BDA754ECB, netMic: 0x37B77A35) encrypted using Primary Network Key (index: 0)
11:48:19.084460 -> 0x00E2EF57A368E5EC2AF28D1E0BDA754ECB37B77A35
11:48:28.110502 Resending Access PDU (opcode: 0x8201, parameters: 0x)
11:48:28.115367 Sending Upper Transport PDU (encrypted data: 0xC43B, transMic: 0xBF8C397C) encrypted using key: App Key 1 (index: 0)
11:48:28.115662 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0xC43BBF8C397C)
11:48:28.116488 Sending Network PDU (ivi: 1, nid: 0x62, ctl: 0, ttl: 5, seq: 2, src: 0001, dst: 0006, transportPdu: 0x900896DABAF285, netMic: 0xE2FB724B) encrypted using Primary Network Key (index: 0)
11:48:28.116750 -> 0x00E29638E5AF05B061E6900896DABAF285E2FB724B
11:48:46.193908 Resending Access PDU (opcode: 0x8201, parameters: 0x)
11:48:46.198682 Sending Upper Transport PDU (encrypted data: 0x748F, transMic: 0xCB945A18) encrypted using key: App Key 1 (index: 0)
11:48:46.198951 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0x748FCB945A18)
11:48:46.199956 Sending Network PDU (ivi: 1, nid: 0x62, ctl: 0, ttl: 5, seq: 3, src: 0001, dst: 0006, transportPdu: 0x7FE788F0535873, netMic: 0xB1783AC6) encrypted using Primary Network Key (index: 0)
11:48:46.200213 -> 0x00E21D4A2917763F14887FE788F0535873B1783AC6
11:48:54.558784 Response to Access PDU (opcode: 0x8201, parameters: 0x) not received (timeout)
11:48:54.559577 GenericOnOffGet() sent from: 0001, to: 0006 timed out
11:48:54.559894 Cancelling messages with op code: 33281, sent from: 0001 to: 0006
After disconnect + reconnect, GenericOnOffServer get of a node with IV 3 -> OK
11:50:48.214379 Cancelling connection...
11:50:48.216635 Disconnected from 1888_592
11:51:06.382606 Central Manager state changed to .poweredOn
11:51:06.382795 Connecting to 1888_592...
11:51:11.579998 Connected to 1888_592
11:51:11.580107 Discovering services...
11:51:13.517007 Service found
11:51:13.517112 Discovering characteristics...
11:51:14.231070 Data In characteristic found
11:51:14.231266 Data Out characteristic found
11:51:14.231553 Enabling notifications...
11:51:14.951657 Data Out notifications enabled
11:51:14.951731 GATT Bearer open and ready
11:51:14.951805 <- 0x010100852FAECB44FDB198000000037903FE82CD081F62
11:51:14.952162 Secure Network beacon (Network ID: 852FAECB44FDB198, IV Index: 3 (normal operation), Key Refresh Flag: false) received (decrypted using key: Primary Network Key (index: 0))
11:51:14.953649 New Proxy connected
11:51:14.954286 Sending AddAddressesToFilter(addresses: Set([2, 1, 65535])) from: 0001 to: 0000
11:51:14.954386 Sending Control Message (opCode: 0x01, data: 0x00010002FFFF)
11:51:14.957756 Sending Network PDU (ivi: 1, nid: 0x62, ctl: 1, ttl: 0, seq: 8, src: 0001, dst: 0000, transportPdu: 0xB5BC94967C7226, netMic: 0x6CD2CA4778430510) encrypted using Primary Network Key (index: 0)
11:51:14.957926 -> 0x02E2C46CA6FB459C4AB1B5BC94967C72266CD2CA4778430510
11:51:32.492008 Sending GenericOnOffGet() from: Primary Element (0x0001), to: 0006
11:51:32.494695 Sending Access PDU (opcode: 0x8201, parameters: 0x)
11:51:32.498522 Sending Upper Transport PDU (encrypted data: 0x3378, transMic: 0x681B945D) encrypted using key: App Key 1 (index: 0)
11:51:32.498644 Sending Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0x3378681B945D)
11:51:32.499350 Sending Network PDU (ivi: 1, nid: 0x62, ctl: 0, ttl: 5, seq: 9, src: 0001, dst: 0006, transportPdu: 0x2421955EDB452F, netMic: 0x191C8E63) encrypted using Primary Network Key (index: 0)
11:51:32.499771 -> 0x00E21DF48A92A8E612B42421955EDB452F191C8E63
11:51:32.769676 <- 0x00E224BA773D7F8DC11A6F59E77567445DD5651B712539DE68
11:51:32.770276 Network PDU (ivi: 1, nid: 0x62, ctl: 0, ttl: 3, seq: 0, src: 0006, dst: 0001, transportPdu: 0x6F59E77567445DD5651B71, netMic: 0x2539DE68) received
11:51:32.774564 Segmented Access Message (akf: 1, aid: 0x2B, szmic: 0, seqZero: 0, segO: 0, segN: 0, data: 0x667A9375A1F00C) received (decrypted using key: Primary Network Key (index: 0))
11:51:32.774640 Access Message (akf: 1, aid: 0x2B, szmic: 0, data: 0x667A9375A1F00C) received
11:51:32.774799 Sending ACK (seqZero: 0, blockAck: 0x00000001)
11:51:32.775059 Upper Transport PDU (encrypted data: 0x667A93, transMic: 0x75A1F00C) received
11:51:32.775444 Response Access PDU (opcode: 0x8204, parameters: 0x01) received (decrypted using key: App Key 1 (index: 0))
11:51:32.775908 GenericOnOffStatus(isOn: true, targetState: nil, remainingTime: nil) received from: 0006, to: 0001
11:51:32.776015 Local Generic OnOff Client model on Primary Element (0x0001) not bound to key: App Key 1 (index: 0)
11:51:32.776163 GenericOnOffStatus(isOn: true, targetState: nil, remainingTime: nil) already decoded as GenericOnOffStatus(isOn: true, targetState: nil, remainingTime: nil)
11:51:32.777139 Sending Network PDU (ivi: 1, nid: 0x62, ctl: 1, ttl: 5, seq: 10, src: 0001, dst: 0006, transportPdu: 0x861CFBA4EFDCA1, netMic: 0x9AE983D9971C04A5) encrypted using Primary Network Key (index: 0)
11:51:32.777302 -> 0x00E26103A185F0027972861CFBA4EFDCA19AE983D9971C04A5
IV 4 is equal to IV 3, I didn't go any further.
Android
Simply can't get past IV 1. When stepping to IV 3 the app gets the SNB indicating IV 3 (first active and then normal operation) but, when sending messages, the node can't decrypt the PDU sent by the app. With the same setup, I tried to get a GenericOnOff state of a node taking advantage of another generic node (built on nRF52840-DK) provisioned on the same mesh, it works fine.
I also tried to provision a new node into a mesh with IV 3 and with all the other already provisioned nodes powered off (like the test did with iOS described above) and found out that the new node is provisioned with IV 0 instead of 3. Shouldn't the app provision the node with IV 3 like iOS?
Here I gathered a bunch of logs retrivied while testing with IV updates with Android
GenericOnOffServer get of a node -> OK
12-12 12:15:54.599 V GenericOnOffServerActivity: Sending message to element's unicast address: 0x0002
12-12 12:15:54.601 V MeshTransport: Src address: 0001
12-12 12:15:54.601 V MeshTransport: Dst address: 0002
12-12 12:15:54.601 V MeshTransport: Key: F12657C49927329C8302B7659684E548
12-12 12:15:54.601 V MeshTransport: akf: 1
12-12 12:15:54.601 V MeshTransport: aid: 29
12-12 12:15:54.601 V MeshTransport: aszmic: 0
12-12 12:15:54.601 V MeshTransport: Sequence number: 29
12-12 12:15:54.601 V MeshTransport: Access message opcode: 8201
12-12 12:15:54.601 V MeshTransport: Access message parameters:
12-12 12:15:54.602 V AccessLayer: Created Access PDU 8201
12-12 12:15:54.602 V UpperTransportLayer: Application nonce: 010000001D0001000200000000
12-12 12:15:54.603 V UpperTransportLayer: Encrypted upper transport pdu: A9FDF6485EBC
12-12 12:15:54.603 V LowerTransportLayer: Unsegmented Lower transport access PDU 5DA9FDF6485EBC
12-12 12:15:54.603 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:15:54.603 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:15:54.603 V NetworkLayer: Sequence Number: 00001D
12-12 12:15:54.604 V NetworkLayer: Encrypted Network payload: 38A3ED488F3D09473AEB33975A
12-12 12:15:54.611 I Quality : Skipped: false 1 cost 17.864248 refreshRate 0 processName no.nordicsemi.android.nrfmeshprovisioner
12-12 12:15:54.617 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-D8-48-F7-FD-D7-DE-38-A3-ED-48-8F-3D-09-47-3A-EB-33-97-5A
12-12 12:15:54.625 V MeshManagerApi: MeshNetwork pdu sent: 0x001BD848F7FDD7DE38A3ED488F3D09473AEB33975A
12-12 12:15:55.209 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-BC-5E-69-15-E5-36-DC-A4-3C-22-72-44-D1-F4-A0-79-34-60-A2-6E-B3-52-38
12-12 12:15:55.209 V MeshManagerApi: Received network pdu: 0x001BBC5E6915E536DCA43C227244D1F4A0793460A26EB35238
12-12 12:15:55.210 V BaseMeshMessageHandler: Sequence number of received Network PDU: 14
12-12 12:15:55.210 V NetworkLayer: TTL for received message: 3
12-12 12:15:55.210 V NetworkLayer: Dst: 0x0001
12-12 12:15:55.211 V NetworkLayer: Received a segmented access message from: 0002
12-12 12:15:55.211 V LowerTransportLayer: SEG O: 0
12-12 12:15:55.211 V LowerTransportLayer: SEG N: 0
12-12 12:15:55.211 V LowerTransportLayer: Last SeqAuth value 12
12-12 12:15:55.211 V LowerTransportLayer: Current SeqAuth value 14
12-12 12:15:55.211 V LowerTransportLayer: Starting incomplete timer for src: 0002
12-12 12:15:55.211 V BlockAcknowledgementMessage: Block ack value: 1
12-12 12:15:55.211 V LowerTransportLayer: TTL: 5
12-12 12:15:55.211 V LowerTransportLayer: Duration: 400
12-12 12:15:55.211 V DefaultNoOperationMessageState: Message reassembly may not be completed yet!
12-12 12:15:55.611 V LowerTransportLayer: Acknowledgement timer expiring
12-12 12:15:55.611 V BlockAcknowledgementMessage: Block ack: 1
12-12 12:15:55.611 V BlockAcknowledgementMessage: bit count: 0
12-12 12:15:55.611 V LowerTransportLayer: Block acknowledgement payload: 003800000001
12-12 12:15:55.612 V LowerTransportLayer: Creating unsegmented transport control
12-12 12:15:55.612 V LowerTransportLayer: Unsegmented Lower transport control PDU 00003800000001
12-12 12:15:55.612 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:15:55.612 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:15:55.612 V NetworkLayer: Sequence Number: 00001E
12-12 12:15:55.612 V NetworkLayer: Encrypted Network payload: 1182DF824C8DC3E27E50D4699D1D7F7509
12-12 12:15:55.613 V MeshMessageState: Sending acknowledgement: 001B991D92177E241182DF824C8DC3E27E50D4699D1D7F7509
12-12 12:15:55.619 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-99-1D-92-17-7E-24-11-82-DF-82-4C-8D-C3-E2-7E-50-D4-69-9D-1D-7F-75-09
12-12 12:15:55.619 V MeshManagerApi: MeshNetwork pdu sent: 0x001B991D92177E241182DF824C8DC3E27E50D4699D1D7F7509
12-12 12:15:55.952 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-22-A3-3B-46-C5-F4-09-79-7B-39-4E-43-4D-AF-BD-25-34-A4-09-80-51-DD-66
12-12 12:15:55.953 V MeshManagerApi: Received network pdu: 0x001B22A33B46C5F409797B394E434DAFBD2534A4098051DD66
12-12 12:15:55.953 V BaseMeshMessageHandler: Sequence number of received Network PDU: 15
12-12 12:15:55.954 V NetworkLayer: TTL for received message: 3
12-12 12:15:55.954 V NetworkLayer: Dst: 0x0001
12-12 12:15:55.954 V NetworkLayer: Received a segmented access message from: 0002
12-12 12:15:55.954 V LowerTransportLayer: SEG O: 0
12-12 12:15:55.954 V LowerTransportLayer: SEG N: 0
12-12 12:15:55.954 V LowerTransportLayer: Last SeqAuth value 14
12-12 12:15:55.954 V LowerTransportLayer: Current SeqAuth value 14
12-12 12:15:55.954 V LowerTransportLayer: Received segment message count: 1
12-12 12:15:55.954 V BlockAcknowledgementMessage: Block ack value: 1
12-12 12:15:55.955 V BlockAcknowledgementMessage: Block ack: 1
12-12 12:15:55.955 V BlockAcknowledgementMessage: bit count: 0
12-12 12:15:55.955 V LowerTransportLayer: Block acknowledgement payload: 003800000001
12-12 12:15:55.955 V LowerTransportLayer: Creating unsegmented transport control
12-12 12:15:55.955 V LowerTransportLayer: Unsegmented Lower transport control PDU 00003800000001
12-12 12:15:55.955 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:15:55.955 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:15:55.955 V NetworkLayer: Sequence Number: 00001F
12-12 12:15:55.955 V NetworkLayer: Encrypted Network payload: 790909E7AE82D3CAB96DF8474B7D983B1F
12-12 12:15:55.956 V MeshMessageState: Sending acknowledgement: 001BE7823DEBC463790909E7AE82D3CAB96DF8474B7D983B1F
12-12 12:15:55.960 V AccessLayer: Received Access PDU 820400
12-12 12:15:55.960 V GenericOnOffStatus: Received generic on off status from: 0x0002
12-12 12:15:55.960 V GenericOnOffStatus: Present on: false
12-12 12:15:55.962 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-E7-82-3D-EB-C4-63-79-09-09-E7-AE-82-D3-CA-B9-6D-F8-47-4B-7D-98-3B-1F
12-12 12:15:55.967 V MeshManagerApi: MeshNetwork pdu sent: 0x001BE7823DEBC463790909E7AE82D3CAB96DF8474B7D983B1F
GenericOnOffServer set of a node -> OK
12-12 12:17:07.855 V GenericOnOffSet: State: ON
12-12 12:17:07.855 V GenericOnOffSet: Transition steps: 0
12-12 12:17:07.855 V GenericOnOffSet: Transition step resolution: 0
12-12 12:17:07.856 V MeshTransport: Src address: 0001
12-12 12:17:07.856 V MeshTransport: Dst address: 0002
12-12 12:17:07.856 V MeshTransport: Key: F12657C49927329C8302B7659684E548
12-12 12:17:07.856 V MeshTransport: akf: 1
12-12 12:17:07.856 V MeshTransport: aid: 29
12-12 12:17:07.856 V MeshTransport: aszmic: 0
12-12 12:17:07.856 V MeshTransport: Sequence number: 32
12-12 12:17:07.856 V MeshTransport: Access message opcode: 8202
12-12 12:17:07.856 V MeshTransport: Access message parameters: 014B0000
12-12 12:17:07.856 V AccessLayer: Created Access PDU 8202014B0000
12-12 12:17:07.856 V UpperTransportLayer: Application nonce: 01000000200001000200000000
12-12 12:17:07.857 V UpperTransportLayer: Encrypted upper transport pdu: C7634B140D53C62FF054
12-12 12:17:07.858 V LowerTransportLayer: Unsegmented Lower transport access PDU 5DC7634B140D53C62FF054
12-12 12:17:07.858 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:17:07.858 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:17:07.858 V NetworkLayer: Sequence Number: 000020
12-12 12:17:07.859 V NetworkLayer: Encrypted Network payload: D26A11A731D3083CEBAE1D624BCAA803A2
12-12 12:17:07.864 I Quality : Skipped: false 1 cost 14.717614 refreshRate 0 processName no.nordicsemi.android.nrfmeshprovisioner
12-12 12:17:07.871 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-51-67-17-91-2A-7B-D2-6A-11-A7-31-D3-08-3C-EB-AE-1D-62-4B-CA-A8-03-A2
12-12 12:17:07.881 V MeshManagerApi: MeshNetwork pdu sent: 0x001B516717912A7BD26A11A731D3083CEBAE1D624BCAA803A2
12-12 12:17:08.223 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-FB-B4-D5-AD-DE-DE-4E-53-79-1F-3A-13-EF-49-41-E5-CB-53-B7-95-F2-2B-F4
12-12 12:17:08.223 V MeshManagerApi: Received network pdu: 0x001BFBB4D5ADDEDE4E53791F3A13EF4941E5CB53B795F22BF4
12-12 12:17:08.223 V BaseMeshMessageHandler: Sequence number of received Network PDU: 16
12-12 12:17:08.224 V NetworkLayer: TTL for received message: 3
12-12 12:17:08.224 V NetworkLayer: Dst: 0x0001
12-12 12:17:08.224 V NetworkLayer: Received a segmented access message from: 0002
12-12 12:17:08.224 V LowerTransportLayer: SEG O: 0
12-12 12:17:08.224 V LowerTransportLayer: SEG N: 0
12-12 12:17:08.224 V LowerTransportLayer: Last SeqAuth value 14
12-12 12:17:08.224 V LowerTransportLayer: Current SeqAuth value 16
12-12 12:17:08.224 V LowerTransportLayer: Starting incomplete timer for src: 0002
12-12 12:17:08.224 V BlockAcknowledgementMessage: Block ack value: 1
12-12 12:17:08.224 V LowerTransportLayer: TTL: 5
12-12 12:17:08.224 V LowerTransportLayer: Duration: 400
12-12 12:17:08.224 V DefaultNoOperationMessageState: Message reassembly may not be completed yet!
12-12 12:17:08.626 V LowerTransportLayer: Acknowledgement timer expiring
12-12 12:17:08.626 V BlockAcknowledgementMessage: Block ack: 1
12-12 12:17:08.626 V BlockAcknowledgementMessage: bit count: 0
12-12 12:17:08.626 V LowerTransportLayer: Block acknowledgement payload: 004000000001
12-12 12:17:08.626 V LowerTransportLayer: Creating unsegmented transport control
12-12 12:17:08.626 V LowerTransportLayer: Unsegmented Lower transport control PDU 00004000000001
12-12 12:17:08.626 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:17:08.626 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:17:08.626 V NetworkLayer: Sequence Number: 000021
12-12 12:17:08.627 V NetworkLayer: Encrypted Network payload: 99CD172423E14F29242B9CD22F1D98A8D6
12-12 12:17:08.627 V MeshMessageState: Sending acknowledgement: 001BBA4FF66E91DC99CD172423E14F29242B9CD22F1D98A8D6
12-12 12:17:08.634 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-BA-4F-F6-6E-91-DC-99-CD-17-24-23-E1-4F-29-24-2B-9C-D2-2F-1D-98-A8-D6
12-12 12:17:08.634 V MeshManagerApi: MeshNetwork pdu sent: 0x001BBA4FF66E91DC99CD172423E14F29242B9CD22F1D98A8D6
12-12 12:17:09.213 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-95-11-A2-8F-79-2E-69-FB-4B-32-E4-22-F1-16-C2-86-14-68-BB-EE-82-90-E3
12-12 12:17:09.214 V MeshManagerApi: Received network pdu: 0x001B9511A28F792E69FB4B32E422F116C2861468BBEE8290E3
12-12 12:17:09.214 V BaseMeshMessageHandler: Sequence number of received Network PDU: 17
12-12 12:17:09.215 V NetworkLayer: TTL for received message: 3
12-12 12:17:09.215 V NetworkLayer: Dst: 0x0001
12-12 12:17:09.215 V NetworkLayer: Received a segmented access message from: 0002
12-12 12:17:09.215 V LowerTransportLayer: SEG O: 0
12-12 12:17:09.215 V LowerTransportLayer: SEG N: 0
12-12 12:17:09.215 V LowerTransportLayer: Last SeqAuth value 16
12-12 12:17:09.216 V LowerTransportLayer: Current SeqAuth value 16
12-12 12:17:09.216 V LowerTransportLayer: Received segment message count: 1
12-12 12:17:09.216 V BlockAcknowledgementMessage: Block ack value: 1
12-12 12:17:09.216 V BlockAcknowledgementMessage: Block ack: 1
12-12 12:17:09.216 V BlockAcknowledgementMessage: bit count: 0
12-12 12:17:09.216 V LowerTransportLayer: Block acknowledgement payload: 004000000001
12-12 12:17:09.216 V LowerTransportLayer: Creating unsegmented transport control
12-12 12:17:09.216 V LowerTransportLayer: Unsegmented Lower transport control PDU 00004000000001
12-12 12:17:09.216 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:17:09.216 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:17:09.216 V NetworkLayer: Sequence Number: 000022
12-12 12:17:09.217 V NetworkLayer: Encrypted Network payload: D7E27304024AE20AB3F59F74235C30217A
12-12 12:17:09.217 V MeshMessageState: Sending acknowledgement: 001BA1BE8BA7BD39D7E27304024AE20AB3F59F74235C30217A
12-12 12:17:09.221 V AccessLayer: Received Access PDU 820401
12-12 12:17:09.221 V GenericOnOffStatus: Received generic on off status from: 0x0002
12-12 12:17:09.221 V GenericOnOffStatus: Present on: true
12-12 12:17:09.226 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-A1-BE-8B-A7-BD-39-D7-E2-73-04-02-4A-E2-0A-B3-F5-9F-74-23-5C-30-21-7A
12-12 12:17:09.244 V MeshManagerApi: MeshNetwork pdu sent: 0x001BA1BE8BA7BD39D7E27304024AE20AB3F59F74235C30217A
After enabling IV test flag in app and triggering a IV update
SNB saying IV 1, update active
12-12 12:18:37.367 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-02-91-FD-B7-D0-6E-02-2D-2E-00-00-00-01-C4-CD-AD-F3-E9-23-86-9E
12-12 12:18:37.370 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 1, IV Update Active: true, Authentication Value: 0xC4CDADF3E923869E}
12-12 12:18:37.371 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:18:37.371 D MeshManagerApi: Last IV Index: 0
12-12 12:18:37.371 I MeshManagerApi: Applying: 1
SNB saying IV 1, normal operation
12-12 12:19:03.355 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-00-91-FD-B7-D0-6E-02-2D-2E-00-00-00-01-AA-B8-CB-2A-E5-EB-D1-1F
12-12 12:19:03.356 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 1, IV Update Active: false, Authentication Value: 0xAAB8CB2AE5EBD11F}
12-12 12:19:03.357 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:19:03.358 D MeshManagerApi: Last IV Index: 1
12-12 12:19:03.358 I MeshManagerApi: Resetting local sequence numbers to 0
GenericOnOffServer get of a node with IV 1 -> OK
12-12 12:19:40.732 V GenericOnOffServerActivity: Sending message to element's unicast address: 0x0002
12-12 12:19:40.734 V MeshTransport: Src address: 0001
12-12 12:19:40.734 V MeshTransport: Dst address: 0002
12-12 12:19:40.734 V MeshTransport: Key: F12657C49927329C8302B7659684E548
12-12 12:19:40.734 V MeshTransport: akf: 1
12-12 12:19:40.734 V MeshTransport: aid: 29
12-12 12:19:40.734 V MeshTransport: aszmic: 0
12-12 12:19:40.735 V MeshTransport: Sequence number: 1
12-12 12:19:40.735 V MeshTransport: Access message opcode: 8201
12-12 12:19:40.735 V MeshTransport: Access message parameters:
12-12 12:19:40.735 V AccessLayer: Created Access PDU 8201
12-12 12:19:40.735 V UpperTransportLayer: Application nonce: 01000000010001000200000001
12-12 12:19:40.736 V UpperTransportLayer: Encrypted upper transport pdu: 6FFF58548C98
12-12 12:19:40.736 V LowerTransportLayer: Unsegmented Lower transport access PDU 5D6FFF58548C98
12-12 12:19:40.736 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:19:40.736 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:19:40.737 V NetworkLayer: Sequence Number: 000001
12-12 12:19:40.738 V NetworkLayer: Encrypted Network payload: 486A56F80F97915850E3CAE81D
12-12 12:19:40.752 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-9B-14-23-A0-11-D1-5D-48-6A-56-F8-0F-97-91-58-50-E3-CA-E8-1D
12-12 12:19:40.760 V MeshManagerApi: MeshNetwork pdu sent: 0x009B1423A011D15D486A56F80F97915850E3CAE81D
12-12 12:19:41.180 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 00-9B-74-63-35-D8-D6-04-1D-90-5B-6D-AA-A4-2A-0F-88-8B-8B-D2-06-19-BB-3F-B7
12-12 12:19:41.180 V MeshManagerApi: Received network pdu: 0x009B746335D8D6041D905B6DAAA42A0F888B8BD20619BB3FB7
12-12 12:19:41.181 V BaseMeshMessageHandler: Sequence number of received Network PDU: 0
12-12 12:19:41.181 V NetworkLayer: TTL for received message: 3
12-12 12:19:41.181 V NetworkLayer: Dst: 0x0001
12-12 12:19:41.181 V NetworkLayer: Received a segmented access message from: 0002
12-12 12:19:41.181 V LowerTransportLayer: SEG O: 0
12-12 12:19:41.181 V LowerTransportLayer: SEG N: 0
12-12 12:19:41.181 V LowerTransportLayer: Last SeqAuth value 16
12-12 12:19:41.181 V LowerTransportLayer: Current SeqAuth value 16777216
12-12 12:19:41.181 V LowerTransportLayer: Starting incomplete timer for src: 0002
12-12 12:19:41.182 V BlockAcknowledgementMessage: Block ack value: 1
12-12 12:19:41.182 V LowerTransportLayer: TTL: 5
12-12 12:19:41.182 V LowerTransportLayer: Duration: 400
12-12 12:19:41.182 V DefaultNoOperationMessageState: Message reassembly may not be completed yet!
12-12 12:19:41.585 V LowerTransportLayer: Acknowledgement timer expiring
12-12 12:19:41.585 V BlockAcknowledgementMessage: Block ack: 1
12-12 12:19:41.585 V BlockAcknowledgementMessage: bit count: 0
12-12 12:19:41.585 V LowerTransportLayer: Block acknowledgement payload: 000000000001
12-12 12:19:41.586 V LowerTransportLayer: Creating unsegmented transport control
12-12 12:19:41.586 V LowerTransportLayer: Unsegmented Lower transport control PDU 00000000000001
12-12 12:19:41.586 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:19:41.586 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:19:41.586 V NetworkLayer: Sequence Number: 000002
12-12 12:19:41.586 V NetworkLayer: Encrypted Network payload: DD9C6E2DF9158190689A9C6D412A8F416D
12-12 12:19:41.586 V MeshMessageState: Sending acknowledgement: 009B87E04BBCF496DD9C6E2DF9158190689A9C6D412A8F416D
12-12 12:19:41.591 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-9B-87-E0-4B-BC-F4-96-DD-9C-6E-2D-F9-15-81-90-68-9A-9C-6D-41-2A-8F-41-6D
12-12 12:19:41.592 V MeshManagerApi: MeshNetwork pdu sent: 0x009B87E04BBCF496DD9C6E2DF9158190689A9C6D412A8F416D
12-12 12:19:41.919 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 00-9B-6A-8D-26-2F-C2-78-FA-15-99-C8-9D-5C-C3-E6-12-51-03-6A-42-C3-2D-7D-6B
12-12 12:19:41.919 V MeshManagerApi: Received network pdu: 0x009B6A8D262FC278FA1599C89D5CC3E61251036A42C32D7D6B
12-12 12:19:41.920 V BaseMeshMessageHandler: Sequence number of received Network PDU: 1
12-12 12:19:41.920 V NetworkLayer: TTL for received message: 3
12-12 12:19:41.920 V NetworkLayer: Dst: 0x0001
12-12 12:19:41.921 V NetworkLayer: Received a segmented access message from: 0002
12-12 12:19:41.921 V LowerTransportLayer: SEG O: 0
12-12 12:19:41.921 V LowerTransportLayer: SEG N: 0
12-12 12:19:41.921 V LowerTransportLayer: Last SeqAuth value 16777216
12-12 12:19:41.921 V LowerTransportLayer: Current SeqAuth value 16777216
12-12 12:19:41.921 V LowerTransportLayer: Received segment message count: 1
12-12 12:19:41.921 V BlockAcknowledgementMessage: Block ack value: 1
12-12 12:19:41.921 V BlockAcknowledgementMessage: Block ack: 1
12-12 12:19:41.921 V BlockAcknowledgementMessage: bit count: 0
12-12 12:19:41.921 V LowerTransportLayer: Block acknowledgement payload: 000000000001
12-12 12:19:41.921 V LowerTransportLayer: Creating unsegmented transport control
12-12 12:19:41.922 V LowerTransportLayer: Unsegmented Lower transport control PDU 00000000000001
12-12 12:19:41.922 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:19:41.922 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:19:41.922 V NetworkLayer: Sequence Number: 000003
12-12 12:19:41.922 V NetworkLayer: Encrypted Network payload: 5D41C1A1E74F241EBD8B3F5792650C9FAE
12-12 12:19:41.923 V MeshMessageState: Sending acknowledgement: 009BD0A84057202B5D41C1A1E74F241EBD8B3F5792650C9FAE
12-12 12:19:41.926 V AccessLayer: Received Access PDU 820401
12-12 12:19:41.926 V GenericOnOffStatus: Received generic on off status from: 0x0002
12-12 12:19:41.926 V GenericOnOffStatus: Present on: true
12-12 12:19:41.931 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-9B-D0-A8-40-57-20-2B-5D-41-C1-A1-E7-4F-24-1E-BD-8B-3F-57-92-65-0C-9F-AE
12-12 12:19:41.940 V MeshManagerApi: MeshNetwork pdu sent: 0x009BD0A84057202B5D41C1A1E74F241EBD8B3F5792650C9FAE
Triggering a new IV update
SNB saying IV 2, update active
12-12 12:21:17.498 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-02-91-FD-B7-D0-6E-02-2D-2E-00-00-00-02-51-40-75-5B-AB-38-5C-35
12-12 12:21:17.500 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 2, IV Update Active: true, Authentication Value: 0x5140755BAB385C35}
12-12 12:21:17.501 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:21:17.502 D MeshManagerApi: Last IV Index: 1
12-12 12:21:17.502 I MeshManagerApi: Applying: 2
SNB saying IV 2, normal operation
12-12 12:21:46.952 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-00-91-FD-B7-D0-6E-02-2D-2E-00-00-00-02-8C-8C-EC-4E-6A-40-4B-D2
12-12 12:21:46.953 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 2, IV Update Active: false, Authentication Value: 0x8C8CEC4E6A404BD2}
12-12 12:21:46.954 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:21:46.955 D MeshManagerApi: Last IV Index: 2
12-12 12:21:46.955 I MeshManagerApi: Resetting local sequence numbers to 0
GenericOnOffServer get of a node with IV 2 -> FAIL
// Unfortunately, I forgot to get the logs here but you can see the one with IV 3 that have the same problem.
After disconnect + reconnect, GenericOnOffServer get of a node with IV 2 -> OK
12-12 12:28:10.747 D BluetoothGatt: cancelOpen() - device: E4:9A:F7:DD:7A:B1
12-12 12:28:10.753 V s : Disconnecting...
12-12 12:28:10.759 D BluetoothGatt: onClientConnectionState() - status=0 clientIf=12 device=E4:9A:F7:DD:7A:B1
12-12 12:28:10.760 I BleManager: Disconnected
12-12 12:28:10.760 D BluetoothGatt: close()
12-12 12:28:10.760 D BluetoothGatt: unregisterApp() - mClientIf=12
12-12 12:28:10.762 V s : Disconnected
12-12 12:28:13.416 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:28:13.419 D BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=11 mScannerId=0
12-12 12:28:39.016 D AA : Connect issued
12-12 12:28:39.018 D BluetoothGatt: connect() - device: E4:9A:F7:DD:7A:B1, auto: false, eattSupport: false
12-12 12:28:39.018 D BluetoothGatt: registerApp()
12-12 12:28:39.018 D BluetoothGatt: registerApp() - UUID=a4e90e74-4b2d-4d20-bfd8-d48a132b3a1c
12-12 12:28:39.020 15007 15890 D BluetoothGatt: onClientRegistered() - status=0 clientIf=12
12-12 12:28:39.486 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:28:41.991 D BluetoothGatt: onClientConnectionState() - status=0 clientIf=12 device=E4:9A:F7:DD:7A:B1
12-12 12:28:41.991 I BleManager: Connected to E4:9A:F7:DD:7A:B1
12-12 12:28:42.293 D BluetoothGatt: discoverServices() - device: E4:9A:F7:DD:7A:B1
12-12 12:28:42.703 15007 15890 D BluetoothGatt: onConnectionUpdated() - Device=E4:9A:F7:DD:7A:B1 interval=198 latency=0 timeout=400 status=0
12-12 12:28:45.178 15007 15890 D BluetoothGatt: onConnectionUpdated() - Device=E4:9A:F7:DD:7A:B1 interval=6 latency=0 timeout=500 status=0
12-12 12:28:45.300 15007 15890 D BluetoothGatt: onSearchComplete() = Device=E4:9A:F7:DD:7A:B1 Status=0
12-12 12:28:45.301 I BleManager: Services discovered
12-12 12:28:45.301 D BluetoothGatt: configureMTU() - device: E4:9A:F7:DD:7A:B1 mtu: 517
12-12 12:28:45.320 15007 15890 D BluetoothGatt: onConfigureMTU() - Device=E4:9A:F7:DD:7A:B1 mtu=69 status=0
12-12 12:28:45.321 I BleManager: MTU changed to: 69
12-12 12:28:45.321 D BluetoothGatt: setCharacteristicNotification() - uuid: 00002ade-0000-1000-8000-00805f9b34fb enable: true
12-12 12:28:45.343 I BleManager: Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
12-12 12:28:45.343 I BleManager: Notifications enabled
12-12 12:28:45.379 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-00-91-FD-B7-D0-6E-02-2D-2E-00-00-00-02-8C-8C-EC-4E-6A-40-4B-D2
12-12 12:28:45.388 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:28:45.391 D BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=11 mScannerId=0
12-12 12:28:45.398 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 2, IV Update Active: false, Authentication Value: 0x8C8CEC4E6A404BD2}
12-12 12:28:45.399 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:28:45.399 D MeshManagerApi: Last IV Index: 2
12-12 12:28:45.424 D BluetoothGatt: onConnectionUpdated() - Device=E4:9A:F7:DD:7A:B1 interval=198 latency=0 timeout=400 status=0
12-12 12:28:58.216 V GenericOnOffServerActivity: Sending message to element's unicast address: 0x0002
12-12 12:28:58.216 V MeshTransport: Src address: 0001
12-12 12:28:58.216 V MeshTransport: Dst address: 0002
12-12 12:28:58.216 V MeshTransport: Key: F12657C49927329C8302B7659684E548
12-12 12:28:58.216 V MeshTransport: akf: 1
12-12 12:28:58.216 V MeshTransport: aid: 29
12-12 12:28:58.216 V MeshTransport: aszmic: 0
12-12 12:28:58.216 V MeshTransport: Sequence number: 15
12-12 12:28:58.216 V MeshTransport: Access message opcode: 8201
12-12 12:28:58.216 V MeshTransport: Access message parameters:
12-12 12:28:58.216 V AccessLayer: Created Access PDU 8201
12-12 12:28:58.216 V UpperTransportLayer: Application nonce: 010000000F0001000200000002
12-12 12:28:58.216 V UpperTransportLayer: Encrypted upper transport pdu: 1ECDF19DBDA8
12-12 12:28:58.216 V LowerTransportLayer: Unsegmented Lower transport access PDU 5D1ECDF19DBDA8
12-12 12:28:58.216 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:28:58.216 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:28:58.216 V NetworkLayer: Sequence Number: 00000F
12-12 12:28:58.217 V NetworkLayer: Encrypted Network payload: BC98B60D18DF7BC961E735E70E
12-12 12:28:58.225 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-0D-D2-48-0D-D3-6A-BC-98-B6-0D-18-DF-7B-C9-61-E7-35-E7-0E
12-12 12:28:58.244 V MeshManagerApi: MeshNetwork pdu sent: 0x001B0DD2480DD36ABC98B60D18DF7BC961E735E70E
12-12 12:28:58.544 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-5E-F6-6B-4D-B8-45-BE-4C-7B-C1-BA-7C-64-1F-B1-CE-6E-42-C0-D4-57-9A-DB
12-12 12:28:58.544 V MeshManagerApi: Received network pdu: 0x001B5EF66B4DB845BE4C7BC1BA7C641FB1CE6E42C0D4579ADB
12-12 12:28:58.545 V BaseMeshMessageHandler: Sequence number of received Network PDU: 9
12-12 12:28:58.545 V NetworkLayer: TTL for received message: 3
12-12 12:28:58.545 V NetworkLayer: Dst: 0x0001
12-12 12:28:58.545 V NetworkLayer: Received a segmented access message from: 0002
12-12 12:28:58.545 V LowerTransportLayer: SEG O: 0
12-12 12:28:58.545 V LowerTransportLayer: SEG N: 0
12-12 12:28:58.545 V LowerTransportLayer: Last SeqAuth value 33554439
12-12 12:28:58.545 V LowerTransportLayer: Current SeqAuth value 33554441
12-12 12:28:58.545 V LowerTransportLayer: Starting incomplete timer for src: 0002
12-12 12:28:58.545 V BlockAcknowledgementMessage: Block ack value: 1
12-12 12:28:58.545 V LowerTransportLayer: TTL: 5
12-12 12:28:58.545 V LowerTransportLayer: Duration: 400
12-12 12:28:58.545 V DefaultNoOperationMessageState: Message reassembly may not be completed yet!
12-12 12:28:58.947 V LowerTransportLayer: Acknowledgement timer expiring
12-12 12:28:58.947 V BlockAcknowledgementMessage: Block ack: 1
12-12 12:28:58.947 V BlockAcknowledgementMessage: bit count: 0
12-12 12:28:58.947 V LowerTransportLayer: Block acknowledgement payload: 002400000001
12-12 12:28:58.947 V LowerTransportLayer: Creating unsegmented transport control
12-12 12:28:58.947 V LowerTransportLayer: Unsegmented Lower transport control PDU 00002400000001
12-12 12:28:58.947 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:28:58.947 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:28:58.947 V NetworkLayer: Sequence Number: 000010
12-12 12:28:58.947 V NetworkLayer: Encrypted Network payload: F1F65389EA12EFD9229DC1574DC78DF4A6
12-12 12:28:58.947 V MeshMessageState: Sending acknowledgement: 001BAF4DBBFF2488F1F65389EA12EFD9229DC1574DC78DF4A6
12-12 12:28:58.953 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-AF-4D-BB-FF-24-88-F1-F6-53-89-EA-12-EF-D9-22-9D-C1-57-4D-C7-8D-F4-A6
12-12 12:28:58.953 V MeshManagerApi: MeshNetwork pdu sent: 0x001BAF4DBBFF2488F1F65389EA12EFD9229DC1574DC78DF4A6
12-12 12:28:59.287 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-A8-38-AB-41-47-95-D5-BE-57-6A-7F-15-C6-03-81-5D-77-FD-FB-A3-6F-92-B1
12-12 12:28:59.287 V MeshManagerApi: Received network pdu: 0x001BA838AB414795D5BE576A7F15C603815D77FDFBA36F92B1
12-12 12:28:59.287 V BaseMeshMessageHandler: Sequence number of received Network PDU: 10
12-12 12:28:59.287 V NetworkLayer: TTL for received message: 3
12-12 12:28:59.287 V NetworkLayer: Dst: 0x0001
12-12 12:28:59.287 V NetworkLayer: Received a segmented access message from: 0002
12-12 12:28:59.287 V LowerTransportLayer: SEG O: 0
12-12 12:28:59.287 V LowerTransportLayer: SEG N: 0
12-12 12:28:59.287 V LowerTransportLayer: Last SeqAuth value 33554441
12-12 12:28:59.287 V LowerTransportLayer: Current SeqAuth value 33554441
12-12 12:28:59.287 V LowerTransportLayer: Received segment message count: 1
12-12 12:28:59.287 V BlockAcknowledgementMessage: Block ack value: 1
12-12 12:28:59.287 V BlockAcknowledgementMessage: Block ack: 1
12-12 12:28:59.287 V BlockAcknowledgementMessage: bit count: 0
12-12 12:28:59.287 V LowerTransportLayer: Block acknowledgement payload: 002400000001
12-12 12:28:59.287 V LowerTransportLayer: Creating unsegmented transport control
12-12 12:28:59.287 V LowerTransportLayer: Unsegmented Lower transport control PDU 00002400000001
12-12 12:28:59.287 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:28:59.287 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:28:59.287 V NetworkLayer: Sequence Number: 000011
12-12 12:28:59.287 V NetworkLayer: Encrypted Network payload: 6344DAB17E71A81F1DAFB1CF7FD51A10B2
12-12 12:28:59.288 V MeshMessageState: Sending acknowledgement: 001BFBFF3AA902786344DAB17E71A81F1DAFB1CF7FD51A10B2
12-12 12:28:59.290 V AccessLayer: Received Access PDU 820401
12-12 12:28:59.291 V GenericOnOffStatus: Received generic on off status from: 0x0002
12-12 12:28:59.291 V GenericOnOffStatus: Present on: true
12-12 12:28:59.310 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-FB-FF-3A-A9-02-78-63-44-DA-B1-7E-71-A8-1F-1D-AF-B1-CF-7F-D5-1A-10-B2
12-12 12:28:59.318 V MeshManagerApi: MeshNetwork pdu sent: 0x001BFBFF3AA902786344DAB17E71A81F1DAFB1CF7FD51A10B2
_Triggering a new IV update_
SNB saying IV 3, update active
12-12 12:30:23.231 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-02-91-FD-B7-D0-6E-02-2D-2E-00-00-00-03-AC-CC-C1-8F-DB-AB-B3-BC
12-12 12:30:23.232 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 3, IV Update Active: true, Authentication Value: 0xACCCC18FDBABB3BC}
12-12 12:30:23.233 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:30:23.233 D MeshManagerApi: Last IV Index: 2
12-12 12:30:23.233 I MeshManagerApi: Applying: 3
SNB saying IV 3, normal operation
12-12 12:31:17.184 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-00-91-FD-B7-D0-6E-02-2D-2E-00-00-00-03-E2-F9-1D-15-C0-15-7B-86
12-12 12:31:17.185 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 3, IV Update Active: false, Authentication Value: 0xE2F91D15C0157B86}
12-12 12:31:17.185 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:31:17.185 D MeshManagerApi: Last IV Index: 3
12-12 12:31:17.185 I MeshManagerApi: Resetting local sequence numbers to 0
GenericOnOffServer get of a node with IV 3 -> FAIL
12-12 12:31:42.874 V GenericOnOffServerActivity: Sending message to element's unicast address: 0x0002
12-12 12:31:42.875 V MeshTransport: Src address: 0001
12-12 12:31:42.875 V MeshTransport: Dst address: 0002
12-12 12:31:42.875 V MeshTransport: Key: F12657C49927329C8302B7659684E548
12-12 12:31:42.875 V MeshTransport: akf: 1
12-12 12:31:42.875 V MeshTransport: aid: 29
12-12 12:31:42.875 V MeshTransport: aszmic: 0
12-12 12:31:42.875 V MeshTransport: Sequence number: 1
12-12 12:31:42.875 V MeshTransport: Access message opcode: 8201
12-12 12:31:42.875 V MeshTransport: Access message parameters:
12-12 12:31:42.875 V AccessLayer: Created Access PDU 8201
12-12 12:31:42.875 V UpperTransportLayer: Application nonce: 01000000010001000200000003
12-12 12:31:42.876 V UpperTransportLayer: Encrypted upper transport pdu: EEB1F0A952B6
12-12 12:31:42.876 V LowerTransportLayer: Unsegmented Lower transport access PDU 5DEEB1F0A952B6
12-12 12:31:42.876 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:31:42.876 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:31:42.876 V NetworkLayer: Sequence Number: 000001
12-12 12:31:42.876 V NetworkLayer: Encrypted Network payload: F1402D40AFCA499E58493DCDB1
12-12 12:31:42.884 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-9B-F3-7D-93-DB-2A-5E-F1-40-2D-40-AF-CA-49-9E-58-49-3D-CD-B1
12-12 12:31:42.896 V MeshManagerApi: MeshNetwork pdu sent: 0x009BF37D93DB2A5EF1402D40AFCA499E58493DCDB1
After disconnect + reconnect, GenericOnOffServer get of a node with IV 3 -> FAIL
12-12 12:35:55.816 D BluetoothGatt: cancelOpen() - device: E4:9A:F7:DD:7A:B1
12-12 12:35:55.822 V s : Disconnecting...
12-12 12:35:55.836 15007 15890 D BluetoothGatt: onClientConnectionState() - status=0 clientIf=12 device=E4:9A:F7:DD:7A:B1
12-12 12:35:55.837 I BleManager: Disconnected
12-12 12:35:55.838 D BluetoothGatt: close()
12-12 12:35:55.839 D BluetoothGatt: unregisterApp() - mClientIf=12
12-12 12:35:55.841 V s : Disconnected
12-12 12:36:13.553 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:36:13.556 15007 15890 D BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=11 mScannerId=0
12-12 12:36:29.184 D AA : Connect issued
12-12 12:36:29.186 D BluetoothGatt: connect() - device: E4:9A:F7:DD:7A:B1, auto: false, eattSupport: false
12-12 12:36:29.186 D BluetoothGatt: registerApp()
12-12 12:36:29.186 D BluetoothGatt: registerApp() - UUID=0f9851fe-af57-4a7c-889b-c02e05b2a1dc
12-12 12:36:29.188 D BluetoothGatt: onClientRegistered() - status=0 clientIf=12
12-12 12:36:29.654 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:36:49.349 D BluetoothGatt: onClientConnectionState() - status=0 clientIf=12 device=E4:9A:F7:DD:7A:B1
12-12 12:36:49.350 I BleManager: Connected to E4:9A:F7:DD:7A:B1
12-12 12:36:49.652 D BluetoothGatt: discoverServices() - device: E4:9A:F7:DD:7A:B1
12-12 12:36:50.032 D BluetoothGatt: onConnectionUpdated() - Device=E4:9A:F7:DD:7A:B1 interval=198 latency=0 timeout=400 status=0
12-12 12:36:52.508 D BluetoothGatt: onConnectionUpdated() - Device=E4:9A:F7:DD:7A:B1 interval=6 latency=0 timeout=500 status=0
12-12 12:36:52.619 D BluetoothGatt: onSearchComplete() = Device=E4:9A:F7:DD:7A:B1 Status=0
12-12 12:36:52.620 I BleManager: Services discovered
12-12 12:36:52.620 D BluetoothGatt: configureMTU() - device: E4:9A:F7:DD:7A:B1 mtu: 517
12-12 12:36:52.639 D BluetoothGatt: onConfigureMTU() - Device=E4:9A:F7:DD:7A:B1 mtu=69 status=0
12-12 12:36:52.639 I BleManager: MTU changed to: 69
12-12 12:36:52.640 D BluetoothGatt: setCharacteristicNotification() - uuid: 00002ade-0000-1000-8000-00805f9b34fb enable: true
12-12 12:36:52.661 I BleManager: Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
12-12 12:36:52.661 I BleManager: Notifications enabled
12-12 12:36:52.699 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-00-91-FD-B7-D0-6E-02-2D-2E-00-00-00-03-E2-F9-1D-15-C0-15-7B-86
12-12 12:36:52.712 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:36:52.716 D BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=11 mScannerId=0
12-12 12:36:52.724 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 3, IV Update Active: false, Authentication Value: 0xE2F91D15C0157B86}
12-12 12:36:52.725 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:36:52.725 D MeshManagerApi: Last IV Index: 3
12-12 12:36:52.889 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:37:07.754 V GenericOnOffServerActivity: Sending message to element's unicast address: 0x0002
12-12 12:37:07.755 V MeshTransport: Src address: 0001
12-12 12:37:07.755 V MeshTransport: Dst address: 0002
12-12 12:37:07.755 V MeshTransport: Key: F12657C49927329C8302B7659684E548
12-12 12:37:07.755 V MeshTransport: akf: 1
12-12 12:37:07.755 V MeshTransport: aid: 29
12-12 12:37:07.755 V MeshTransport: aszmic: 0
12-12 12:37:07.755 V MeshTransport: Sequence number: 3
12-12 12:37:07.755 V MeshTransport: Access message opcode: 8201
12-12 12:37:07.755 V MeshTransport: Access message parameters:
12-12 12:37:07.755 V AccessLayer: Created Access PDU 8201
12-12 12:37:07.755 V UpperTransportLayer: Application nonce: 01000000030001000200000003
12-12 12:37:07.755 V UpperTransportLayer: Encrypted upper transport pdu: CC6ABFF28A64
12-12 12:37:07.756 V LowerTransportLayer: Unsegmented Lower transport access PDU 5DCC6ABFF28A64
12-12 12:37:07.756 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:37:07.756 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:37:07.756 V NetworkLayer: Sequence Number: 000003
12-12 12:37:07.756 V NetworkLayer: Encrypted Network payload: E1E3E1F50CAA6B84F63C605DD0
12-12 12:37:07.765 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-9B-B5-AF-D8-4C-33-B7-E1-E3-E1-F5-0C-AA-6B-84-F6-3C-60-5D-D0
12-12 12:37:07.772 V MeshManagerApi: MeshNetwork pdu sent: 0x009BB5AFD84C33B7E1E3E1F50CAA6B84F63C605DD0
12-12 12:37:21.096 V GenericOnOffServerActivity: Sending message to element's unicast address: 0x0002
12-12 12:37:21.097 V MeshTransport: Src address: 0001
12-12 12:37:21.097 V MeshTransport: Dst address: 0002
12-12 12:37:21.097 V MeshTransport: Key: F12657C49927329C8302B7659684E548
12-12 12:37:21.097 V MeshTransport: akf: 1
12-12 12:37:21.097 V MeshTransport: aid: 29
12-12 12:37:21.097 V MeshTransport: aszmic: 0
12-12 12:37:21.097 V MeshTransport: Sequence number: 4
12-12 12:37:21.097 V MeshTransport: Access message opcode: 8201
12-12 12:37:21.097 V MeshTransport: Access message parameters:
12-12 12:37:21.097 V AccessLayer: Created Access PDU 8201
12-12 12:37:21.097 V UpperTransportLayer: Application nonce: 01000000040001000200000003
12-12 12:37:21.098 V UpperTransportLayer: Encrypted upper transport pdu: F29334F23208
12-12 12:37:21.098 V LowerTransportLayer: Unsegmented Lower transport access PDU 5DF29334F23208
12-12 12:37:21.098 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:37:21.098 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:37:21.098 V NetworkLayer: Sequence Number: 000004
12-12 12:37:21.098 V NetworkLayer: Encrypted Network payload: 996F0B009733A3DB6793088625
12-12 12:37:21.108 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-9B-E7-D0-03-58-03-93-99-6F-0B-00-97-33-A3-DB-67-93-08-86-25
12-12 12:37:21.116 V MeshManagerApi: MeshNetwork pdu sent: 0x009BE7D003580393996F0B009733A3DB6793088625
_Triggering a new IV update_
SNB saying IV 4, update active
12-12 12:39:57.438 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-02-91-FD-B7-D0-6E-02-2D-2E-00-00-00-04-09-B2-AC-41-4C-36-35-FD
12-12 12:39:57.440 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 4, IV Update Active: true, Authentication Value: 0x09B2AC414C3635FD}
12-12 12:39:57.440 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:39:57.440 D MeshManagerApi: Last IV Index: 3
12-12 12:39:57.441 I MeshManagerApi: Applying: 4
SNB saying IV 4, normal operation
12-12 12:40:43.959 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-00-91-FD-B7-D0-6E-02-2D-2E-00-00-00-04-A5-5A-E7-41-0A-76-36-39
12-12 12:40:43.960 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 4, IV Update Active: false, Authentication Value: 0xA55AE7410A763639}
12-12 12:40:43.960 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:40:43.960 D MeshManagerApi: Last IV Index: 4
12-12 12:40:43.960 I MeshManagerApi: Resetting local sequence numbers to 0
GenericOnOffServer get of a node with IV 4 -> FAIL
12-12 12:41:30.580 V GenericOnOffServerActivity: Sending message to element's unicast address: 0x0002
12-12 12:41:30.580 V MeshTransport: Src address: 0001
12-12 12:41:30.580 V MeshTransport: Dst address: 0002
12-12 12:41:30.580 V MeshTransport: Key: F12657C49927329C8302B7659684E548
12-12 12:41:30.580 V MeshTransport: akf: 1
12-12 12:41:30.580 V MeshTransport: aid: 29
12-12 12:41:30.580 V MeshTransport: aszmic: 0
12-12 12:41:30.580 V MeshTransport: Sequence number: 1
12-12 12:41:30.580 V MeshTransport: Access message opcode: 8201
12-12 12:41:30.580 V MeshTransport: Access message parameters:
12-12 12:41:30.580 V AccessLayer: Created Access PDU 8201
12-12 12:41:30.581 V UpperTransportLayer: Application nonce: 01000000010001000200000004
12-12 12:41:30.581 V UpperTransportLayer: Encrypted upper transport pdu: 490623FDF560
12-12 12:41:30.581 V LowerTransportLayer: Unsegmented Lower transport access PDU 5D490623FDF560
12-12 12:41:30.581 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:41:30.581 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:41:30.581 V NetworkLayer: Sequence Number: 000001
12-12 12:41:30.581 V NetworkLayer: Encrypted Network payload: 30057E9DA8CF90E63F064FC8A1
12-12 12:41:30.597 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-6A-F5-7F-01-86-83-30-05-7E-9D-A8-CF-90-E6-3F-06-4F-C8-A1
12-12 12:41:30.598 V MeshManagerApi: MeshNetwork pdu sent: 0x001B6AF57F01868330057E9DA8CF90E63F064FC8A1
After disconnect + reconnect, GenericOnOffServer get of a node with IV 3 -> FAIL
12-12 12:44:21.871 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:44:21.873 D BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=7 mScannerId=0
12-12 12:44:25.701 D AA : Connect issued
12-12 12:44:25.703 D BluetoothGatt: connect() - device: E4:9A:F7:DD:7A:B1, auto: false, eattSupport: false
12-12 12:44:25.703 D BluetoothGatt: registerApp()
12-12 12:44:25.703 D BluetoothGatt: registerApp() - UUID=2e337557-0b01-46ae-9ad3-ebc00a6a08d1
12-12 12:44:25.705 D BluetoothGatt: onClientRegistered() - status=0 clientIf=11
12-12 12:44:26.161 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:44:27.043 15007 15890 D BluetoothGatt: onClientConnectionState() - status=0 clientIf=11 device=E4:9A:F7:DD:7A:B1
12-12 12:44:27.043 I BleManager: Connected to E4:9A:F7:DD:7A:B1
12-12 12:44:27.347 D BluetoothGatt: discoverServices() - device: E4:9A:F7:DD:7A:B1
12-12 12:44:27.658 15007 15890 D BluetoothGatt: onConnectionUpdated() - Device=E4:9A:F7:DD:7A:B1 interval=198 latency=0 timeout=400 status=0
12-12 12:44:30.134 15007 15890 D BluetoothGatt: onConnectionUpdated() - Device=E4:9A:F7:DD:7A:B1 interval=6 latency=0 timeout=500 status=0
12-12 12:44:30.238 15007 15890 D BluetoothGatt: onSearchComplete() = Device=E4:9A:F7:DD:7A:B1 Status=0
12-12 12:44:30.238 I BleManager: Services discovered
12-12 12:44:30.239 D BluetoothGatt: configureMTU() - device: E4:9A:F7:DD:7A:B1 mtu: 517
12-12 12:44:30.257 15007 15890 D BluetoothGatt: onConfigureMTU() - Device=E4:9A:F7:DD:7A:B1 mtu=69 status=0
12-12 12:44:30.258 I BleManager: MTU changed to: 69
12-12 12:44:30.258 D BluetoothGatt: setCharacteristicNotification() - uuid: 00002ade-0000-1000-8000-00805f9b34fb enable: true
12-12 12:44:30.280 I BleManager: Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
12-12 12:44:30.280 I BleManager: Notifications enabled
12-12 12:44:30.319 I BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-00-91-FD-B7-D0-6E-02-2D-2E-00-00-00-04-A5-5A-E7-41-0A-76-36-39
12-12 12:44:30.331 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:44:30.335 D BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=7 mScannerId=0
12-12 12:44:30.341 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 4, IV Update Active: false, Authentication Value: 0xA55AE7410A763639}
12-12 12:44:30.341 D MeshManagerApi: Secure Network Beacon authenticated.
12-12 12:44:30.341 D MeshManagerApi: Last IV Index: 4
12-12 12:44:30.378 D BluetoothGatt: onConnectionUpdated() - Device=E4:9A:F7:DD:7A:B1 interval=198 latency=0 timeout=400 status=0
12-12 12:44:30.483 D BluetoothAdapter: isLeEnabled(): ON
12-12 12:44:37.501 V GenericOnOffServerActivity: Sending message to element's unicast address: 0x0002
12-12 12:44:37.501 V MeshTransport: Src address: 0001
12-12 12:44:37.501 V MeshTransport: Dst address: 0002
12-12 12:44:37.501 V MeshTransport: Key: F12657C49927329C8302B7659684E548
12-12 12:44:37.501 V MeshTransport: akf: 1
12-12 12:44:37.501 V MeshTransport: aid: 29
12-12 12:44:37.501 V MeshTransport: aszmic: 0
12-12 12:44:37.501 V MeshTransport: Sequence number: 4
12-12 12:44:37.501 V MeshTransport: Access message opcode: 8201
12-12 12:44:37.501 V MeshTransport: Access message parameters:
12-12 12:44:37.502 V AccessLayer: Created Access PDU 8201
12-12 12:44:37.502 V UpperTransportLayer: Application nonce: 01000000040001000200000004
12-12 12:44:37.502 V UpperTransportLayer: Encrypted upper transport pdu: 56BBE38D87D4
12-12 12:44:37.502 V LowerTransportLayer: Unsegmented Lower transport access PDU 5D56BBE38D87D4
12-12 12:44:37.502 V NetworkLayer: Encryption key: A8EF6DE6A6E4065D42493D3A79799F4A
12-12 12:44:37.502 V NetworkLayer: Privacy key: C96C809D214F63728E825B481B40A5B3
12-12 12:44:37.502 V NetworkLayer: Sequence Number: 000004
12-12 12:44:37.503 V NetworkLayer: Encrypted Network payload: C65DD7205B8B4A27F1DEE0AC1A
12-12 12:44:37.513 I BleManager: Data written to 00002add-0000-1000-8000-00805f9b34fb, value: (0x) 00-1B-A5-A6-E9-B1-B0-5A-C6-5D-D7-20-5B-8B-4A-27-F1-DE-E0-AC-1A
12-12 12:44:37.519 V MeshManagerApi: MeshNetwork pdu sent: 0x001BA5A6E9B1B05AC65DD7205B8B4A27F1DEE0AC1A
I didn't go any further.
Conclusion
Is the above behavior what you expect?
Regarding
GenericOnOffServer get of a node with IV 3 -> FAIL (timeout)
How many nodes do you have in your network? This looks like the Proxy Node or some relays have not been updated with the IV index. The ivi is set to 1, so seems like the IV index is used correctly. If that worked for IV Index 1 and 2, in my opinion should also for 3... Do you see logs from all nodes that they have received and applied the IV index update to 3?
There are 3 nodes: A, B, and C:
- Node A is the one I used to trigger the IV update
- Node B is the one I tested with the GenericOnOff get/set
- Node C.. I only provisioned it to increase the number of devices in the same mesh :)
If that worked for IV Index 1 and 2, in my opinion should also for 3...
I agree but at the moment the tests I've done say otherwise
Do you see logs from all nodes that they have received and applied the IV index update to 3?
How can I be sure? From the app logs I only see the SNB from the proxy.
Hi @philips77, I ran a few tests again with the same 3 devices: with nRF Mesh Android (3.2.4) I was able to reach IV 4, normal op, and still able to get/set a GenericOnOff Server, nice!
Then I tried to step to IV 5 with app offline from the network, I checked that all 3 devices are on IV 5, normal op, and then connect to the network with app.
02-14 12:42:05.259 18703 18703 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 5, IV Update Active: false, Authentication Value: 0xA76ADC85DD599381}
02-14 12:42:05.259 18703 18703 D MeshManagerApi: Secure Network Beacon authenticated.
02-14 12:42:05.259 18703 18703 D MeshManagerApi: Last IV Index: 4
02-14 12:42:05.259 18703 18703 W MeshManagerApi: Discarding beacon IV Index: 5, IV Update Active: false, last 4, changed: 1h ago, test mode: true
What was the last IV Update Active flag value when you put the phone offline? It can only update by 1 step, that is from IV Index 4 (flag active) to IV Index 5 (normal operation) unless you wait for 96h. If the flag was false, that it the last IV Index was 4 (normal operation), then it can't accept IV Index 5 with normal operation.
It takes at least 96h to update by 1 step:
- IV Index X normal operation -> IV Index X update active
- IV Index X update active -> IV Index X+1 virtual operation
The test mode can shorten the transition by 96h only.
I did the following:
- put the app offline from the mesh, last IV with app online was IV 4 normal operation
- stepped the mesh to IV 5 update active
- stepped the mesh to IV 5 normal operation
- put the app online on the same mesh with test flag enabled
02-14 12:42:05.259 18703 18703 D MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 5, IV Update Active: false, Authentication Value: 0xA76ADC85DD599381} 02-14 12:42:05.259 18703 18703 D MeshManagerApi: Secure Network Beacon authenticated. 02-14 12:42:05.259 18703 18703 D MeshManagerApi: Last IV Index: 4 02-14 12:42:05.259 18703 18703 W MeshManagerApi: Discarding beacon IV Index: 5, IV Update Active: false, last 4, changed: 1h ago, test mode: true
Putting that aside for a moment, I want to ask you a question: Hypothetically speaking, if I create a mesh with some devices, then wait a discrete amount of time to make the mesh increase its IV to 2 for example (like a year?), what happens if I go back to this mesh and I want to do any edits to those devices? And what if I want to add a new device to mesh?
Hypothetically speaking, if I create a mesh with some devices, then wait a discrete amount of time to make the mesh increase its IV to 2 for example (like a year?), what happens if I go back to this mesh and I want to do any edits to those devices? And what if I want to add a new device to mesh?
I can answer that for you with experience; I have a mesh of 150 devices deployed at a client site. Last contact with the mesh from the provisioner was in early December. The mesh is quite high traffic; each device publishes a message every ten minutes. Just recently (read: today) I went back with the tablet I was using as a provisioner to integrate a new node. I saw all the symptoms you did: I can connect to the mesh but I cannot do "Get TTL" or any other commands. Provisioning a new device is successful but stops at getting composition of the device. I presume the device got updated to the correct IV index via a SNB packet but my tablet did not. It and the rest of the mesh are operating but I cannot configure or do anything from my tablet. IV index is now 2.
@philips77 I think there is an issue with the app not picking up the SNBs properly. I connected directly to a node that I configured as a SNB prior to this and sat there for an hour with IV test mode on. The tablet's messages are still being refused. I tried changing the provisioner's address as well but I'm having no luck.
@Halo3fanz same here, I have more than one mesh with these symptoms, I also have a custom app built on an older nordic sdk that I want to upgrade to the latest version but, before doing it, wanna be sure that all these problem are fixed.
Hi, are you also testing with iOS version of nRF Mesh? Do you have logs from Android version showing how the Snb is handled in connection?
Hi, are you also testing with iOS version of nRF Mesh? Do you have logs from Android version showing how the Snb is handled in connection?
Sure, its verbose but here you go: nrf_mesh_app_adb_log.txt
At line 1900-1944, you'll find an example of a command, likely the Get TTL command being sent out. SNBs are being received at lines 712 and 1715 indicating IV index of 2 but the next lines show it discarding the beacon and remaining at IV index of 0.
I don't have an iOS device but I'll try and get one.
@Halo3fanz same here, I have more than one mesh with these symptoms, I also have a custom app built on an older nordic sdk that I want to upgrade to the latest version but, before doing it, wanna be sure that all these problem are fixed.
Are you using nRF SDK for mesh or the new NCS?
Are you using nRF SDK for mesh or the new NCS?
The custom app uses:
- nRF SDK mesh v2.3.1 / Android
- nRF SDK mesh v2.2.3 / iOS
I want to update to the latest version so I'm running some tests before doing it.
What is NCS?
What is NCS?
The nRF Connect SDK is a new Zephyr-based SDK that Nordic is moving all its existing SDKs into. Regular BLE, Mesh and other RF technologies included. It's a radically different paradigm than their previous SDKs.
I assume you're updating to nRF SDK for Mesh v5.0,0? FYI, this SDK will not be updated further as it is in maintenance mode and Nordic recommends everyone to use NCS for new designs.
What is NCS?
The nRF Connect SDK is a new Zephyr-based SDK that Nordic is moving all its existing SDKs into. Regular BLE, Mesh and other RF technologies included. It's a radically different paradigm than their previous SDKs.
I assume you're updating to nRF SDK for Mesh v5.0,0? FYI, this SDK will not be updated further as it is in maintenance mode and Nordic recommends everyone to use NCS for new designs.
Actually, I'm interested in updating to nRF Mesh v3.2.4. Didn't know the existence of NCS, thank you!
Let's see what @philips77 has to say about your log.
I just tested with an iOS device, and it worked! It worked without even enabling the IV test mode. I was able to provision and configure new devices with no issues. What does this mean? I much prefer the Android app's UI so I would still like this to be fixed.
IV Index is now 3 by the way.
If we're not getting replies from the dev team here, should we go to the devzone and find answers there?