Receiving data in from Generic On Off Client through pyACI

Question

Hi, I am trying to get event messages on the terminal from a Generic On Off (GOO) Client node. I have the provisioned the mesh using the pyAci through another board running the serial example. I followed the steps in the serial examples, which work as expected. I configured the device and models with application keys and group address, as well as setting the publication address. (In the code below it is only set on the first model, but tried both and also setting subscription address in previous attempts). I have also tried to create a virtual GOO Server to listen to events. I guess I am expecting some RX messages to pop up in the shell when the board buttons are pressed, however I could be on completely the wrong track. How can I get data in from the mesh devices? Many thanks in advance, Tim Environment: OSX nrf5SDK for Mesh v310 2 x NRF52832 BK boards one with serial example and second with light switch client example interactive_pyaci shell: In [1]: db = MeshDB("database/example_database.json") In [2]: p = Provisioner(device, db) 2019-06-12 23:11:36,356 - DEBUG - tty.usbmodem0006822145041: TX: 616954ec8b19f34449178c4e4b22c155379fc89697ca63b07115b49cbbe8b6e654e0d421ab792c5782f572c69491f13463dd8d67a04b9ab8ffa04411967f0b48795441fa89a0dced7390b74ecb08c300bdca5e63a17745a67d722ecb49380a838c8d In [3]: 2019-06-12 23:11:36,370 - DEBUG - tty.usbmodem0006822145041: RX: 03845384 2019-06-12 23:11:36,370 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 83, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,370 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,371 - DEBUG - tty.usbmodem0006822145041: TX: 059f01000100 2019-06-12 23:11:36,371 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,371 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,372 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,372 - DEBUG - tty.usbmodem0006822145041: TX: 1392000018eed9c2a56add85049ffc3c59ad0e12 2019-06-12 23:11:36,372 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,372 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,373 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,373 - DEBUG - tty.usbmodem0006822145041: TX: 1597000000004f68ad85d9f48ac8589df665b6b49b8a 2019-06-12 23:11:36,374 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,374 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,375 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,375 - DEBUG - tty.usbmodem0006822145041: TX: 1597010000002aa2a6ded5a0798ceab5787ca3ae39fc 2019-06-12 23:11:36,376 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,376 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,376 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,376 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,384 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,384 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,384 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,384 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,385 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,385 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,385 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,385 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,385 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,385 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,386 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,386 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,386 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,386 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,386 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,386 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,387 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,387 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,387 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,388 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,389 - DEBUG - tty.usbmodem0006822145041: RX: 03840084 2019-06-12 23:11:36,389 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 0, 'status': 132, 'data': bytearray(b'')}} 2019-06-12 23:11:36,390 - ERROR - tty.usbmodem0006822145041: None: ERROR_INVALID_LENGTH 2019-06-12 23:11:36,390 - DEBUG - tty.usbmodem0006822145041: RX: 03849f00 2019-06-12 23:11:36,390 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 159, 'status': 0, 'data': bytearray(b'')}} 2019-06-12 23:11:36,391 - INFO - tty.usbmodem0006822145041: Success 2019-06-12 23:11:36,391 - DEBUG - tty.usbmodem0006822145041: RX: 058492000000 2019-06-12 23:11:36,392 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 146, 'status': 0, 'data': bytearray(b'\x00\x00')}} 2019-06-12 23:11:36,393 - INFO - tty.usbmodem0006822145041: SubnetAdd: {'subnet_handle': 0} 2019-06-12 23:11:36,395 - DEBUG - tty.usbmodem0006822145041: RX: 058497000000 2019-06-12 23:11:36,395 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 151, 'status': 0, 'data': bytearray(b'\x00\x00')}} 2019-06-12 23:11:36,397 - INFO - tty.usbmodem0006822145041: AppkeyAdd: {'appkey_handle': 0} 2019-06-12 23:11:36,398 - DEBUG - tty.usbmodem0006822145041: RX: 058497000100 2019-06-12 23:11:36,398 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 151, 'status': 0, 'data': bytearray(b'\x01\x00')}} 2019-06-12 23:11:36,399 - INFO - tty.usbmodem0006822145041: AppkeyAdd: {'appkey_handle': 1} In [3]: In [3]: In [3]: p.scan_start() 2019-06-12 23:11:46,071 - DEBUG - tty.usbmodem0006822145041: TX: 0161 In [4]: 2019-06-12 23:11:46,076 - DEBUG - tty.usbmodem0006822145041: RX: 03846100 2019-06-12 23:11:46,076 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 97, 'status': 0, 'data': bytearray(b'')}} 2019-06-12 23:11:46,077 - INFO - tty.usbmodem0006822145041: Success 2019-06-12 23:11:46,092 - DEBUG - tty.usbmodem0006822145041: RX: 1ac09db77a0526b8734988639509c242d107e60001c8639509c2c2 2019-06-12 23:11:46,092 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: ProvUnprovisionedReceived, data: {'uuid': bytearray(b'\x9d\xb7z\x05&\xb8sI\x88c\x95 \xc2B\xd1\x07'), 'rssi': -26, 'gatt_supported': 0, 'adv_addr_type': 1, 'adv_addr': bytearray(b'\xc8c\x95 \xc2\xc2')}} 2019-06-12 23:11:46,093 - INFO - tty.usbmodem0006822145041: Received UUID 9db77a0526b8734988639509c242d107 with RSSI: -26 dB 2019-06-12 23:11:48,101 - DEBUG - tty.usbmodem0006822145041: RX: 1ac09db77a0526b8734988639509c242d107e70001c8639509c2c2 2019-06-12 23:11:48,101 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: ProvUnprovisionedReceived, data: {'uuid': bytearray(b'\x9d\xb7z\x05&\xb8sI\x88c\x95 \xc2B\xd1\x07'), 'rssi': -25, 'gatt_supported': 0, 'adv_addr_type': 1, 'adv_addr': bytearray(b'\xc8c\x95 \xc2\xc2')}} In [4]: In [4]: In [4]: In [4]: p.scan_stop()2019-06-12 23:11:50,120 - DEBUG - tty.usbmodem0006822145041: RX: 1ac09db77a0526b8734988639509c242d107e60001c8639509c2c2 2019-06-12 23:11:50,120 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: ProvUnprovisionedReceived, data: {'uuid': bytearray(b'\x9d\xb7z\x05&\xb8sI\x88c\x95 \xc2B\xd1\x07'), 'rssi': -26, 'gatt_supported': 0, 'adv_addr_type': 1, 'adv_addr': bytearray(b'\xc8c\x95 \xc2\xc2')}} In [4]: p.scan_stop() 2019-06-12 23:11:50,144 - DEBUG - tty.usbmodem0006822145041: TX: 0162 2019-06-12 23:11:50,158 - DEBUG - tty.usbmodem0006822145041: RX: 03846200 2019-06-12 23:11:50,162 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 98, 'status': 0, 'data': bytearray(b'')}} 2019-06-12 23:11:50,166 - INFO - tty.usbmodem0006822145041: Success In [5]: In [5]: In [5]: p.provision(name="Client") In [6]: 2019-06-12 23:11:55,875 - DEBUG - tty.usbmodem0006822145041: TX: 2d63009db77a0526b8734988639509c242d10718eed9c2a56add85049ffc3c59ad0e120000000000001000000000 2019-06-12 23:11:55,880 - DEBUG - tty.usbmodem0006822145041: RX: 0484630000 2019-06-12 23:11:55,881 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 99, 'status': 0, 'data': bytearray(b'\x00')}} 2019-06-12 23:11:55,881 - INFO - tty.usbmodem0006822145041: Provision: {'context': 0} 2019-06-12 23:11:55,909 - DEBUG - tty.usbmodem0006822145041: RX: 02c100 2019-06-12 23:11:55,911 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: ProvLinkEstablished, data: {'context_id': 0}} 2019-06-12 23:11:55,913 - INFO - tty.usbmodem0006822145041: Link established 2019-06-12 23:11:55,977 - DEBUG - tty.usbmodem0006822145041: RX: 0bc300030001000000000000 2019-06-12 23:11:55,978 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: ProvCapsReceived, data: {'context_id': 0, 'num_elements': 3, 'public_key_type': 0, 'static_oob_types': 1, 'output_oob_size': 0, 'output_oob_actions': 0, 'input_oob_size': 0, 'input_oob_actions': 0}} 2019-06-12 23:11:55,978 - INFO - tty.usbmodem0006822145041: Received capabilities 2019-06-12 23:11:55,978 - INFO - tty.usbmodem0006822145041: Number of elements: 3 2019-06-12 23:11:55,979 - DEBUG - tty.usbmodem0006822145041: TX: 056600000000 2019-06-12 23:11:55,980 - DEBUG - tty.usbmodem0006822145041: RX: 0484660000 2019-06-12 23:11:55,981 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: CmdRsp, data: {'opcode': 102, 'status': 0, 'data': bytearray(b'\x00')}} 2019-06-12 23:11:55,981 - INFO - tty.usbmodem0006822145041: OobUse: {'context': 0} 2019-06-12 23:11:56,172 - DEBUG - tty.usbmodem0006822145041: RX: 62c7006d3c4542b959b5b0635dee1e2dd766df39f84181040c108e479a5757a08250e4a195af93cd2a699b35f44adb3c3f02ec4f22cabb4e720666915f8e93d7b5123a88fd41dd23969ec32f6ea5d1d70563cd3fd8c33bbea526a1b98d3d27dc270c2b 2019-06-12 23:11:56,173 - DEBUG - tty.usbmodem0006822145041: parsed_packet {event: ProvEcdhRequest, data: {'context_id': 0, 'peer_public': bytearray(b'm} In [13]: In [13]: In [13]: device.event_filter_disable() In [14]: gs = GenericOnOffServer() ...: device.model_add(gs) ...: gs.publish_set(0, 1) In [15]: In [15]: In [15]: Segger Debug Terminal: , main.c, 318, ----- BLE Mesh Light Switch Client Demo ----- , main.c, 289, Initializing and adding models , mesh_app_utils.c, 65, Device UUID (raw): 9DB77A0526B8734988639509C242D107 , mesh_app_utils.c, 70, Device UUID : 057AB79D-B826-4973-8863-9509C242D107 , main.c, 112, Successfully provisioned , main.c, 123, Node Address: 0x0010 , config_server.c, 623, dsm_appkey_add(appkey_handle:0 appkey_index:0) , proxy.c, 638, Adv timeout , main.c, 200, Button 0 pressed , main.c, 227, Sending msg: ONOFF SET 1 , main.c, 200, Button 0 pressed , main.c, 227, Sending msg: ONOFF SET 1 , main.c, 156, Acknowledged transfer cancelled. , main.c, 200, Button 1 pressed , main.c, 227, Sending msg: ONOFF SET 0 , main.c, 156, Acknowledged transfer cancelled. , main.c, 152, Acknowledged transfer timeout. , main.c, 200, Button 2 pressed , main.c, 227, Sending msg: ONOFF SET 1 , main.c, 269, Publication not configured for client 2 , main.c, 200, Button 3 pressed , main.c, 227, Sending msg: ONOFF SET 0 , main.c, 269, Publication not configured for client 3 GenericOnOffServer in generic_on_off.py class GenericOnOffServer(Model): GENERIC_ON_OFF_SET = Opcode(0x8202, None, "Generic OnOff Set") GENERIC_ON_OFF_SET_UNACKNOWLEDGED = Opcode(0x8203, None, "Generic OnOff Set Unacknowledged") GENERIC_ON_OFF_GET = Opcode(0x8201, None, "Generic OnOff Get") GENERIC_ON_OFF_STATUS = Opcode(0x8204, None, "Generic OnOff Status") def __init__(self): self.opcodes = [ (self.GENERIC_ON_OFF_SET, self.__generic_on_off_server_event_handler), (self.GENERIC_ON_OFF_SET_UNACKNOWLEDGED, self.__generic_on_off_server_event_handler), (self.GENERIC_ON_OFF_GET, self.__generic_on_off_server_event_handler), (self.GENERIC_ON_OFF_STATUS, self.__generic_on_off_server_event_handler)] self.__tid = 0 super(GenericOnOffServer, self).__init__(self.opcodes) @property def _tid(self): tid = self.__tid self.__tid += 1 if self.__tid >= 255: self.__tid = 0 return tid def __generic_on_off_server_event_handler(self, opcode, message): print("Server Event {} {}".format(opcode, message)) self.logger.debug("Server Event {} {}".format(opcode, message)) mesh database { "$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": "9db77a0526b8734988639509c242d107", "appKeys": [ 0 ], "cid": "0059", "configComplete": false, "crpl": 40, "deviceKey": "8e134fdaa6f80cf523af9384a653e95d", "elements": [ { "index": 0, "location": "0000", "models": [ { "modelId": "0000" }, { "modelId": "0002" } ] }, { "index": 1, "location": "0000", "models": [ { "modelId": "1001", "publish": { "address": 49153, "credentials": 0, "index": 0, "period": 0, "retransmit": { "count": 0, "interval": 50 }, "ttl": 1 } } ] }, { "index": 2, "location": "0000", "models": [ { "modelId": "1001" } ] } ], "features": { "friend": 2, "lowPower": 2, "proxy": 0, "relay": 0 }, "name": "Client", "netKeys": [ 0 ], "pid": "0000", "security": "low", "unicastAddress": 16, "vid": "0000" } ], "provisioners": [ { "UUID": "00000000000000000000000000000000", "allocatedGroupRange": [ { "highAddress": 65279, "lowAddress": 49152 } ], "allocatedUnicastRange": [ { "highAddress": 32767, "lowAddress": 16 } ], "name": "BT Mesh Provisioner" } ], "timestamp": "2019-06-12 23:12:47.736705"

timvan · Answer

After finding the following question I noticed that I had not set the subscription Address for the device https://devzone.nordicsemi.com/f/nordic-q-a/40826/pyaci-serial-configuration-and-model-subscription/160032#160032 
 d[0].send(cmd.AddrPublicationAdd(db.groups[0].address)) should have been d[0].send(cmd.AddrSubscriptionAdd(db.groups[0].address) After changing that I can now receive events.