Interactive PyACI : Group Publish/subscribe with server and client not working properly ?

[ValentinL]

Hello,

I am working with the Interactive PyACI (nRF_SDK_for_Mesh 4.0.0 with boards nRF52832). I followed the tutorial "demo_configuration" present in the doc folder.
Every works fine, I can scan, provision, bind servers and clients.
Now I want to have a set up where a server send "notification" and other boards, which are client I guess, will get the information = state change (with a genericOnOff).
So I think that correspond to the last point of the tutorial : #### Publishing and subscribing @anchor pyaci_demo_configuration_starting_configuration_5_publishing.
I did as said in the tutorial, It looks like server and client are well configured because I get all correct return message and the the Json file looks correct (see attach).
But when I set the server with gc.set(True), the led on the server board turn on but nothing happen on the client board.
Yet I suppose the led on the client board must turn on since in the tutorial it is written : "You should now be able to use the Generic OnOff client to change the state of the server and observe
that the client also changes its state accordingly".
Is it normal that nothing happen on the client board ? How can we make a proper publishing/subscribing to a group please ? :)

Wainting for an answer, Thank you very much !

Fullscreen example_database (copy).txt Download

{
  "$schema": "",
  "appKeys": [
    {
      "boundNetKey": 0,
      "index": 0,
      "key": "4f68ad85d9f48ac8589df665b6b49b8a",
      "name": "lights"
    },
    {
      "boundNetKey": 0,
      "index": 1,
      "key": "2aa2a6ded5a0798ceab5787ca3ae39fc",
      "name": "locks"
    }
  ],
  "groups": [
    {
      "address": 49153,
      "name": "Room 1",
      "parentAddress": 0
    },
    {
      "address": 49154,
      "name": "Room 2",
      "parentAddress": 0
    }
  ],
  "ivIndex": 0,
  "ivUpdate": 0,
  "meshName": "BT Mesh",
  "meshUUID": "01020304050607080102030405060708",
  "netKeys": [
    {
      "index": 0,
      "key": "18eed9c2a56add85049ffc3c59ad0e12",
      "minSecurity": "low",
      "name": "root",
      "phase": 0
    }
  ],
  "nodes": [
    {
      "UUID": "1578bc42364ea4409a9b364acb9bf093",
      "cid": "0059",
      "configComplete": false,
      "crpl": 40,
      "deviceKey": "eb9f7f71eafde62a9998e37ce8b80005",
      "elements": [
        {
          "index": 0,
          "location": "0000",
          "models": [
            {
              "modelId": "0000"
            },
            {
              "modelId": "0002"
            }
          ]
        },
        {
          "index": 1,
          "location": "0000",
          "models": [
            {
              "bind": [
                0
              ],
              "modelId": "1001",
              "subscribe": [
                49153
              ]
            }
          ]
        },
        {
          "index": 2,
          "location": "0000",
          "models": [
            {
              "modelId": "1001"
            }
          ]
        }
      ],
      "features": {
        "friend": 2,
        "lowPower": 2,
        "proxy": 0,
        "relay": 0
      },
      "netKeys": [
        0
      ],
      "pid": "0000",
      "security": "low",
      "unicastAddress": 16,
      "vid": "0000"
    },
    {
      "UUID": "eb1be75149de7d4ea9f4e67a497feaaf",
      "cid": "0059",
      "configComplete": false,
      "crpl": 40,
      "deviceKey": "4a811697dfeed1c4a7652e5b49f26f91",
      "elements": [
        {
          "index": 0,
          "location": "0000",
          "models": [
            {
              "modelId": "0000"
            },
            {
              "modelId": "0002"
            },
            {
              "bind": [
                0
              ],
              "modelId": "1000",
              "publish": {
                "address": 49153,
                "credentials": 0,
                "index": 0,
                "period": 0,
                "retransmit": {
                  "count": 0,
                  "interval": 50
                },
                "ttl": 1
              }
            }
          ]
        }
      ],
      "features": {
        "friend": 2,
        "lowPower": 2,
        "proxy": 0,
        "relay": 0
      },
      "netKeys": [
        0
      ],
      "pid": "0000",
      "security": "low",
      "unicastAddress": 19,
      "vid": "0000"
    }
  ],
  "provisioners": [
    {
      "UUID": "00000000000000000000000000000000",
      "allocatedGroupRange": [
        {
          "highAddress": 65279,
          "lowAddress": 49152
        }
      ],
      "allocatedUnicastRange": [
        {
          "highAddress": 32767,
          "lowAddress": 16
        }
      ],
      "name": "BT Mesh Provisioner"
    }
  ],
  "timestamp": "2020-06-04 14:21:52.297678"
}

[Hung Bui]

Hi ValentinL, 

It's would be nice to get some more logging in formation on the client side and the server side. 
We would need to know at which step it failed. 

Please note that the client only listen to the status replied directly to it, not the status change broadcast by the server (AFAIK) . So if you send the command to change the LED state from the client (by click the button on the client) you should see LED get updated on both the client and the server. 

[ValentinL]

Here is the command I do and the log I receive (I custom some log command and log but you should easily understand)

1) db = MeshDB(pathlib)
2) p = Provisioner(device, db)
None: ERROR_INVALID_LENGTH
None: ERROR_INVALID_LENGTH
None: ERROR_INVALID_LENGTH
None: ERROR_INVALID_LENGTH
None: ERROR_INVALID_LENGTH
Success
SubnetAdd: {'subnet_handle': 0}
AppkeyAdd: {'appkey_handle': 0}
AppkeyAdd: {'appkey_handle': 1}

3) p.scan_start()
StartScan
Success
Received UUID 1578bc42364ea4409a9b364acb9bf093 with RSSI: -43 dB
Received UUID eb1be75149de7d4ea9f4e67a497feaaf with RSSI: -29 dB

4) p.scan_stop()
5) p.provision (I do a loop on every device I scan as unprov, here I have 2) so I get this log :
unprov liste = [bytearray(b'\x15x\xbcB6N\xa4@\x9a\x9b6J\xcb\x9b\xf0\x93'), bytearray(b'\xeb\x1b\xe7QI\xde}N\xa9\xf4\xe6zI\x7f\xea\xaf')]
prov_list ... = [bytearray(b'\x15x\xbcB6N\xa4@\x9a\x9b6J\xcb\x9b\xf0\x93')]
unprov liste = [bytearray(b'\xeb\x1b\xe7QI\xde}N\xa9\xf4\xe6zI\x7f\xea\xaf')]
Provision: {'context': 0}
Received capabilities
Number of elements: 3
OobUse: {'context': 0}
EcdhSecret: {'context': 0}
Provisioning complete
    Address(es): 0x10-0x12
    Device key: 26ed34d9ce3afb941401a430f7365684
    Network key: 18eed9c2a56add85049ffc3c59ad0e12
Adding device key to subnet %d 0
Adding publication address of root element
len_prov = 1
uuid =  1578bc42364ea4409a9b364acb9bf093
{'1578bc42364ea4409a9b364acb9bf093': (8, 0)}
liste des node provisionnés = [bytearray(b'\x15x\xbcB6N\xa4@\x9a\x9b6J\xcb\x9b\xf0\x93')]
unprov liste = [bytearray(b'\xeb\x1b\xe7QI\xde}N\xa9\xf4\xe6zI\x7f\xea\xaf')]
prov_list ... = [bytearray(b'\x15x\xbcB6N\xa4@\x9a\x9b6J\xcb\x9b\xf0\x93'), bytearray(b'\xeb\x1b\xe7QI\xde}N\xa9\xf4\xe6zI\x7f\xea\xaf')]
unprov liste = []
DevkeyAdd: {'devkey_handle': 8}
AddrPublicationAdd: {'address_handle': 0}
Provision: {'context': 0}
Received capabilities
Number of elements: 1
OobUse: {'context': 0}
EcdhSecret: {'context': 0}
Provisioning complete
    Address(es): 0x13-0x13
    Device key: 470a4f2755a63b453e93e786740b643c
    Network key: 18eed9c2a56add85049ffc3c59ad0e12
Adding device key to subnet %d 0
Adding publication address of root element
len_prov = 2
uuid =  eb1be75149de7d4ea9f4e67a497feaaf
{'1578bc42364ea4409a9b364acb9bf093': (8, 0), 'eb1be75149de7d4ea9f4e67a497feaaf': (9, 1)}
liste des node provisionnés = [bytearray(b'\x15x\xbcB6N\xa4@\x9a\x9b6J\xcb\x9b\xf0\x93'), bytearray(b'\xeb\x1b\xe7QI\xde}N\xa9\xf4\xe6zI\x7f\xea\xaf')]
DevkeyAdd: {'devkey_handle': 9}
AddrPublicationAdd: {'address_handle': 1}

i now config the server :
cc = ConfigurationClient(db)
device.model_add(cc)
cc.publish_set(key_handle,addr_handle)
6) cc.composition_data_get()
received composition data (page {}): 0 {
"cid": "0059",
"pid": "0000",
"vid": "0000",
"crpl": 40,
"features": {
"relay": 0,
"proxy": 0,
"friend": 2,
"low_power": 2
},
"elements": [
{
"index": 0,
"location": "0000",
"models": [
{
"modelId": "0000"
},
{
"modelId": "0002"
},
{
"modelId": "1000"
}
]
}
]
}
7) cc.appkey_add(0)
8) cc.model_app_bind(db.nodes[node_id].unicast_address, 0, mt.ModelId(0x1000))
Appkey bind 0 succeded for subnet 0 at node 19
Model app bind status: AccessStatus.SUCCESS
Appkey bind 0 to model 1000 at 0013

9) cc.model_publication_set(db.nodes[node_id].unicast_address, mt.ModelId(0x1000), mt.Publish(db.groups[0].address, index=0, ttl=1))
Publication status for 1000 at element 19 to {'address': c001, 'index': 0, 'ttl': 1, 'period': 0, 'retransmit': {'count': 0, 'interval_steps': 0, 'interval': 50}, 'credentials': <FriendshipCredentials.DISABLED: 0>}

So after this logs, for me everytings works fine and I have my server that can publish to the group address 0. You see that in the Json file I already send.

Now then I configure the client, The device is already provisionned since I made a loop (as said above).
Now I configure the client that must subscribe to the group address :
1) cc.composition_data_get()
received composition data (page {}): 0 {
  "cid": "0059",
  "pid": "0000",
  "vid": "0000",
  "crpl": 40,
  "features": {
    "relay": 0,
    "proxy": 0,
    "friend": 2,
    "low_power": 2
  },
  "elements": [
    {
      "index": 0,
      "location": "0000",
      "models": [
        {
          "modelId": "0000"
        },
        {
          "modelId": "0002"
        }
      ]
    },
    {
      "index": 1,
      "location": "0000",
      "models": [
        {
          "modelId": "1001"
        }
      ]
    },
    {
      "index": 2,
      "location": "0000",
      "models": [
        {
          "modelId": "1001"
        }
      ]
    }
  ]
}

2) cc.appkey_add(0)
3) cc.model_app_bind(db.nodes[node_id].unicast_address + 1, 0, mt.ModelId(0x1001))
Appkey bind 0 succeded for subnet 0 at node 16
Model app bind status: AccessStatus.SUCCESS
Appkey bind 0 to model 1001 at 0011

4) cc.model_subscription_add(db.nodes[node_id].unicast_address + 1, db.groups[0].address, mt.ModelId(0x1001))
Added subscription c001 to model 1001 at element 17

And that's it. Now my server and client are configured (as written in the tutorial).
I do now : gc.set(True)
Of course before I configure the GenericOnOffClient :
  gc = GenericOnOffClient()
  device.model_add(gc)
  gc.publish_set(0, 1) --> the server board correspond to (0,1)

With the gc.set(true) The led on the server board turn on (what is just because the device is well binded).
But nothing happen on the Client board. I don't see where the "publication" and "subscribe" act here ?
I though the server should publish to the group address when I do "gc.set(True)" and that the client should receive this state change because he subscribe and so the led on the client board should also turn on.
Is it just that the client receive the info correctly but it is not implemented that the led turn on ?
Can you explain me what I should see ?

Thanks !! I hope you have all information needed.

[Hung Bui]

Please get the log on the light switch client and the light switch server. It's the RTT log that printed out on RTT Viewer.