Frame counter not being set by both deCONZ and directly with serial protocol

[puddly]

I've been trying to write network settings to a Conbee II and am unable to progress with one part of this puzzle: setting the frame counter.

The serial protocol describes a "0x27" network parameter that indeed yields the correct network frame counter when read, but writing this parameter does not actually do anything. I've tried variations of bringing the network online, writing the parameter, and bringing it offline in every possible order, with 5s delays, and multiple times in a row to no avail: reading the parameter after a write "works", but after re-connecting to the serial port, the old value is returned once again.

I tried to check how deCONZ itself does it by performing a Phoscon backup, but according to the serial traffic, the frame counter is never actually written!

I'm testing this at the moment by directly editing a Phoscon backup archive and changing the frame counter value. deCONZ logs the following:

deconz    | 22:06:45:055 Warning frame counter 52316187 (0x031E481B) lower than previous one 4276993775 (0xFEEDBEEF)

0xFEEDBEEF (4276993775) is what I had in my edited backup. I'm testing with deconzcommunity/deconz:beta, Conbee II running firmware 0x26720700.

The source code for https://github.com/dresden-elektronik/deconz-rest-plugin/blob/0f370be484acad5e8b8820a13cf237d28c478836/backup.cpp#L484 isn't public (as far as I can tell) and it seems to me that apsCtrl->setParameter does more than just send WRITE_PARAMETER.

What conditions need to be present for the write to happen/succeed?

Attached is a log file of deCONZ running with as many verbosity settings as I could find. In it I performed a backup and restore through Phoscon.

Thanks!

deconz.log

[puddly]

@manup any suggestions? Here are the commands I'm currently sending (actual source code here):

CHANGE_NETWORK_STATE  NET_OFFLINE

# Poll the device state until it's OFFLINE
DEVICE_STATE

WRITE_PARAMETER aps_designed_coordinator  1
WRITE_PARAMETER nwk_address               nwk
WRITE_PARAMETER mac_address               ieee
WRITE_PARAMETER channel_mask              mask
WRITE_PARAMETER nwk_panid                 panid
WRITE_PARAMETER aps_extended_panid        extended_pan_id
WRITE_PARAMETER nwk_update_id             nwk_update_id
WRITE_PARAMETER nwk_key                   0, network_key
WRITE_PARAMETER nwk_frame_counter         frame_counter

# Reading the parameter works, but the new value will not persist
READ_PARAMETER nwk_frame_counter

WRITE_PARAMETER trust_center_address      tc_addr
WRITE_PARAMETER link_key                  tc_addr, tc_link_key
WRITE_PARAMETER security_mode             PRECONFIGURED_NETWORK_KEY

CHANGE_NETWORK_STATE  NET_CONNECTED

# Poll the device state until it's CONNECTED
DEVICE_STATE

The docs state:

Outgoing security frame counter. It shall be only set initially when joining or forming a network. ... By reading parameters the current configuration can be obtained. Be aware that this configuration might not reflect the active configuration, since changes to parameters affect the network operation only as soon as it’s stopped and started again.

The change not taking effect seems to be what's happening here.

[manup]

Hmm the 0x27 is correct, note that the parameter is 4 bytes U32 little endian.

The internal code to write the parameter is:

    if (oldFrameCounter > newFrameCounter)
    {
        DBG_Printf(DBG_INFO, "Warning frame counter %u (0x%08X) lower than previous one %u (0x%08X)\n",
                   newFrameCounter, newFrameCounter, oldFrameCounter, oldFrameCounter);

        if ((oldFrameCounter - newFrameCounter) > (UINT32_MAX / 2))
        {
            // frame counter wrap
        }
        else if (deCONZ::master()->deviceProtocolVersion() >= DECONZ_PROTOCOL_VERSION_1_12)
        {
            uint8_t out[4];
            oldFrameCounter += 300;
            put_u32_le(out, &oldFrameCounter);

            DBG_Printf(DBG_INFO, "Raise frame counter to %u (0x%08X)\n", oldFrameCounter, oldFrameCounter);
            deCONZ::master()->writeParameter(ZM_DID_STK_FRAME_COUNTER, out, 4);
        }
    }

Is the status code of writing the frame counter SUCCESS (0x00)?

[puddly]

Yes, it is.

Are there any command line flags I can pass to deCONZ to show these DBG_Printf(DBG_INFO messages? I've modified the Docker image to pass a few more command line arguments (--dbg-prot=$DEBUG_PROT --dbg-wire=$DEBUG_WIRE) and am running it with:

  - DECONZ_WEB_PORT=80
  - DECONZ_WS_PORT=443
  - DECONZ_VNC_MODE=1
  - DEBUG_INFO=10
  - DEBUG_APS=0
  - DEBUG_ZCL=0
  - DEBUG_ZDP=0
  - DEBUG_OTAU=0
  - DEBUG_ERROR=10
  - DEBUG_PROT=10
  - DEBUG_WIRE=10

I've never seen any messages related to the frame counter get logged.

Back to the original problem: I'm sniffing the serial communication between deCONZ and the Conbee so none of my code is involved at this point beyond the packet disassembly, it's all deCONZ <-> Conbee II.

Here's me creating a backup with Phoscon:

>  cmd:READ_PARAMETER seq:164 stat:SUCCESS flen:  8 plen:  1   27
    param:NWK_FRAME_COUNTER

<  cmd:READ_PARAMETER seq:164 stat:SUCCESS flen: 12 plen:  5   27 0F C9 1E 03
    param:NWK_FRAME_COUNTER, data:0F C9 1E 03

The frame counter in the backup matches what's received over serial:

$ tar -axf ~/Downloads/raspbee_gateway_config_2021-12-13.dat  deCONZ.conf -O | jq .frameCounter
52349199
$ python3 -c "print((52349199).to_bytes(4, 'little').hex())"
0fc91e03

According to the code in your comment, editing the Phoscon backup to have a lower frame counter value is required to trigger the write. I changed it to 123 but no WRITE_PARAMETER ever occurs for the frame counter, even though Phoscon says the restore succeeds. All the other parameters are written. With oldFrameCounter=52349199 and newFrameCounter=123, it seems like it would work.

Performing another Phoscon backup (unsurprisingly) doesn't yield the lower frame counter value:

>  cmd:READ_PARAMETER seq:229 stat:SUCCESS flen:  8 plen:  1   27
    param:NWK_FRAME_COUNTER

<  cmd:READ_PARAMETER seq:229 stat:SUCCESS flen: 12 plen:  5   27 06 62 B7 03
    param:NWK_FRAME_COUNTER, data:06 62 B7 03

When I write the frame counter (5000 + 123) with my application, it supposedly succeeds:

# Changing the state from CONNECTED -> OFFLINE -> CONNECTED

>  cmd:WRITE_PARAMETER seq:9 stat:SUCCESS flen: 12 plen:  5   27 03 14 00 00
    param:NWK_FRAME_COUNTER, data:03140000

<  cmd:WRITE_PARAMETER seq:9 stat:SUCCESS flen:  8 plen:  1   27
    param:NWK_FRAME_COUNTER, status:SUCCESS

# Changing the state from CONNECTED -> OFFLINE -> CONNECTED

But after a restart, it reverts:

>  cmd:READ_PARAMETER seq:14 stat:SUCCESS flen:  8 plen:  1   27
    param:NWK_FRAME_COUNTER

<  cmd:READ_PARAMETER seq:14 stat:SUCCESS flen: 12 plen:  5   27 DA 65 B7 03
    param:NWK_FRAME_COUNTER, data:DA 65 B7 03