MessageReceived doesn't reach Python code

pintify commented 4 years ago

I've connected a Raspberry Pi to a network as a node and the messages in the network are reaching the device but it never appears a MessageReceived in the source. The logs of the bluetooth_mesh service show this for each message sent by the emitting node:

mesh/util.c:print_packet() 69903.278 RX: Network [enc] :: 2653f9773df1f7aaa2f6198b8b3ef5c6e9ba628322
mesh/util.c:print_packet() 69903.278 RX: Network [clr] :: 260300000d0001c0004bb1f78567b685c9
mesh/net.c:msg_in_cache() Add 0001 + 00000d + 4bb1f785
mesh/net.c:packet_received() RX: Network 0001 -> c000 : TTL 0x03 : IV : 00000000 SEQ 0x00000d
mesh/net.c:packet_received() RX: App 0x0001 -> 0xc000 : TTL 0x03 : SEQ 0x00000d
mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 4b
mesh/util.c:print_packet() 69903.278 Used App Key: 12121212121212121212121212121212
mesh/util.c:print_packet() 69903.278 Clr Rx: 820400

But the message_received method in ElementInterface is never executed.

michallowasrzechonek-silvair commented 4 years ago

The message seems to be sent to a group address, so you need to subscribe your model first.

pintify commented 4 years ago

In theory, the provisioner is already doing that. Let me show you a more extense part of the driver log, marking the subscription:

mesh/net.c:seg_rxed() RXed (old: 0002 000003 size:12) 1 of 1
mesh/net.c:send_net_ack() Send ACK to Segs: 00000003
mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 00
mesh/util.c:print_packet() 32147.078 Clr Rx: 0000000012121212121212121212121212121212
mesh/cfgmod-server.c:cfg_srv_pkt() CONFIG-SRV-opcode 0x0 size 19 idx 000
mesh/cfgmod-server.c:cfg_srv_pkt() Add/Update AppKey success: Net_Idx 000, App_Idx 000
mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 00
mesh/net.c:send_seg() segN 0 segment 0 seg_off 0
mesh/util.c:print_packet() 32147.079 Clr-Net Tx: 007f00000600030001001b5d53959649e193f19e00000000
mesh/util.c:print_packet() 32147.081 RX: Network [enc] :: 698668609a536f89d234976bb12d8df75ee456a834f49e81
mesh/util.c:print_packet() 32147.081 RX: Network [clr] :: 69ff0000050003000100000800000003
mesh/util.c:print_packet() 32147.081 RX: Network [enc] :: 690e87c460fd43fc2c7924d54cb65fb7ef38650d0141bfed
mesh/util.c:print_packet() 32147.081 RX: Network [clr] :: 697f00000600030001001b5d53959649e193f19e
mesh/util.c:print_packet() 32147.394 RX: Network [enc] :: 69a2759871cccbd4a940624714575a26fc53bcd8a6f9a3289869
mesh/util.c:print_packet() 32147.394 RX: Network [clr] :: 69030000040001000300c24c967f52a1b0368d4e051e
mesh/net.c:msg_in_cache() Add 0001 + 000004 + 52a1b036
mesh/net.c:packet_received() RX: Network 0001 -> 0003 : TTL 0x03 : IV : 00000000 SEQ 0x000004
mesh/net.c:packet_received() RX: App 0x0001 -> 0x0003 : TTL 0x03 : SEQ 0x000004
mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 00
mesh/util.c:print_packet() 32147.394 Clr Rx: 803d030000000110
mesh/cfgmod-server.c:cfg_srv_pkt() CONFIG-SRV-opcode 0x803d size 6 idx 000
mesh/model.c:model_bind_idx() Bind key 0000 to model ffff1001
mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 00
mesh/net.c:send_seg() segN 0 segment 0 seg_off 0
mesh/util.c:print_packet() 32147.395 Clr-Net Tx: 007f0000070003000100596ff3b8acf5b8fc9dec1354a400000000
mesh/util.c:print_packet() 32147.397 RX: Network [enc] :: 69372e0d49f2afdf0a492215ae9a1610da40a6bd9fae7df7c51880
mesh/util.c:print_packet() 32147.397 RX: Network [clr] :: 697f0000070003000100596ff3b8acf5b8fc9dec1354a4
mesh/util.c:print_packet() 32147.572 RX: Network [enc] :: 698c68342bae331b0ded9941e62f21edffaac7dc122c2928ff5e
mesh/util.c:print_packet() 32147.572 RX: Network [clr] :: 690300000500010003006c74cac5807e302e338bd7a9
mesh/net.c:msg_in_cache() Add 0001 + 000005 + 807e302e
mesh/net.c:packet_received() RX: Network 0001 -> 0003 : TTL 0x03 : IV : 00000000 SEQ 0x000005
mesh/net.c:packet_received() RX: App 0x0001 -> 0x0003 : TTL 0x03 : SEQ 0x000005
mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 00
mesh/util.c:print_packet() 32147.572 Clr Rx: 801b030000c00110
mesh/cfgmod-server.c:cfg_srv_pkt() CONFIG-SRV-opcode 0x801b size 6 idx 000

>>>> mesh/model.c:add_sub() Added group subscription c000

mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 00
mesh/net.c:send_seg() segN 0 segment 0 seg_off 0
mesh/util.c:print_packet() 32147.574 Clr-Net Tx: 007f0000080003000100d76240bf32edefb35ce5aed7a000000000
mesh/util.c:print_packet() 32147.575 RX: Network [enc] :: 693f5dceade979cdb9b616557825e1b19dc32a8895ac9d4d891ddf
mesh/util.c:print_packet() 32147.575 RX: Network [clr] :: 697f0000080003000100d76240bf32edefb35ce5aed7a0
mesh/util.c:print_packet() 32147.781 RX: Network [enc] :: 697fac92c65f127754e7ea6f53eaddb00e783f5606
mesh/util.c:print_packet() 32147.781 RX: Network [clr] :: 69030000060001c0004bc0c5b641186dc6
mesh/net.c:msg_in_cache() Add 0001 + 000006 + 4bc0c5b6
mesh/net.c:packet_received() RX: Network 0001 -> c000 : TTL 0x03 : IV : 00000000 SEQ 0x000006
mesh/net.c:packet_received() RX: App 0x0001 -> 0xc000 : TTL 0x03 : SEQ 0x000006
mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 4b
mesh/util.c:print_packet() 32147.781 Used App Key: 12121212121212121212121212121212
mesh/util.c:print_packet() 32147.781 Clr Rx: 820400
mesh/util.c:print_packet() 32149.280 RX: Network [enc] :: 693cf47cba6c79a7b87d2215aa0c97e1983a2591e5
mesh/util.c:print_packet() 32149.280 RX: Network [clr] :: 69030000070001c0004b08f33c33a36556
mesh/net.c:msg_in_cache() Add 0001 + 000007 + 4b08f33c
mesh/net.c:packet_received() RX: Network 0001 -> c000 : TTL 0x03 : IV : 00000000 SEQ 0x000007
mesh/net.c:packet_received() RX: App 0x0001 -> 0xc000 : TTL 0x03 : SEQ 0x000007
mesh/model.c:mesh_model_rx() iv_index 00000000 key_aid = 4b
mesh/util.c:print_packet() 32149.280 Used App Key: 12121212121212121212121212121212
mesh/util.c:print_packet() 32149.280 Clr Rx: 820400

pintify commented 4 years ago

I'm trying with a more contained code. I'm running now two RPis, both with the same bluez and bluetooth_mesh versions. One of them as provisioner and the other as node, in order to narrow down the problem I'm having in this issue.

I'm trying to create the connection but I'm not very sure of the outputs I'm receiving. The sources are:

Provisioner

import asyncio
import secrets
import logging
import sys
from time import sleep
from uuid import UUID

from typing import Dict

from bluetooth_mesh.application import Application, Element
from bluetooth_mesh.models import ConfigClient, HealthClient
from bluetooth_mesh.messages.config import GATTNamespaceDescriptor
from bluetooth_mesh.crypto import ApplicationKey, DeviceKey, NetworkKey

logger = logging.getLogger()

class MainElement(Element):
    LOCATION = GATTNamespaceDescriptor.MAIN
    MODELS = [ConfigClient, HealthClient]

class SampleApplication(Application):
    COMPANY_ID = 0x0136  # Silvair
    PRODUCT_ID = 1
    VERSION_ID = 1
    ELEMENTS = {0: MainElement}
    CRPL = 32768
    PATH = "/org/example/provisioner"

    @property
    def dev_key(self):
        return DeviceKey(secrets.token_bytes(16))

    @property
    def primary_net_key(self):
        return 0, NetworkKey(secrets.token_bytes(16))

    @property
    def app_keys(self):
        return {0: ApplicationKey(secrets.token_bytes(16))}

    async def run(self):
        async with self:
            await self.create_network()
            await self.connect(addr = 0, iv_index = 5)
            await self.management_interface.add_node(UUID('{cb2ce7c3-14e6-514a-9027-5bab0182f54e}'))
            sleep(1)
            logger.info("Node added?")
            sleep(1)

            client = self.elements[0][HealthClient]

            while True:
                await client.attention(0x0001, app_index=0, attention=3)

def main():
    loop = asyncio.get_event_loop()
    app = SampleApplication(loop)
    loop.run_until_complete(app.run())

if __name__ == '__main__':
    logger.setLevel(logging.DEBUG)

    handler = logging.StreamHandler(sys.stdout)
    handler.setLevel(logging.DEBUG)
    formatter = logging.Formatter('%(levelname)s \t %(message)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)

    main()

Provisioner output

root@raspberry:/home/pi# python3 mesh/main.py 
DEBUG    Using selector: EpollSelector
DEBUG    Connecting to D-Bus
INFO     Connecting to org.bluez.mesh
INFO     Registering application
INFO     Create 08ff2811-1446-59aa-859b-b0546d2f403f
INFO     Attach 2a1cefa859fca73e (socket_pair=False, socket_path=None)
INFO     Attached to node /org/bluez/mesh/node08ff2811144659aa859bb0546d2f403f, address: 0001, configuration: defaultdict(<class 'dict'>, {})
INFO     Node added?
DEBUG    Sending: /org/example/provisioner/element0 -> 0001 [app_index 0] HealthOpcode.ATTENTION_SET Container(attention=3)
DEBUG    Sending: /org/example/provisioner/element0 -> 0001 [app_index 0] 800503
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/bluetooth_mesh/models/base.py", line 387, in query
    await asyncio.wait_for(status, timeout=timeout)
  File "/usr/lib/python3.7/asyncio/tasks.py", line 423, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "mesh/main.py", line 95, in <module>
    main()
  File "mesh/main.py", line 83, in main
    loop.run_until_complete(app.run())
  File "/usr/lib/python3.7/asyncio/base_events.py", line 584, in run_until_complete
    return future.result()
  File "mesh/main.py", line 77, in run
    await client.attention(0x0001, app_index=0, attention=3)
  File "/usr/local/lib/python3.7/dist-packages/bluetooth_mesh/models/models.py", line 920, in attention
    status = await self.query(request, status)
  File "/usr/local/lib/python3.7/dist-packages/bluetooth_mesh/models/base.py", line 391, in query
    await sender
  File "/usr/local/lib/python3.7/dist-packages/bluetooth_mesh/models/base.py", line 381, in sender
    await request()
  File "/usr/local/lib/python3.7/dist-packages/bluetooth_mesh/models/base.py", line 285, in send_app
    await self._send_app(destination, app_index, data)
  File "/usr/local/lib/python3.7/dist-packages/bluetooth_mesh/models/base.py", line 259, in _send_app
    await self._node_interface.send(self.element.path, destination, app_index, data)
  File "/usr/local/lib/python3.7/dist-packages/bluetooth_mesh/interfaces.py", line 467, in send
    flags=MessageFlag.NO_REPLY_EXPECTED,
TypeError: method_fn() got an unexpected keyword argument 'flags'

Node

import asyncio
import logging
import sys

from bluetooth_mesh.application import Application, Element
from bluetooth_mesh.models import ConfigServer, HealthServer
from bluetooth_mesh.messages.config import GATTNamespaceDescriptor

logger = logging.getLogger()

class MainElement(Element):
    LOCATION = GATTNamespaceDescriptor.MAIN
    MODELS = [ConfigServer, HealthServer]

class SampleApplication(Application):
    COMPANY_ID = 0x0136  # Silvair
    PRODUCT_ID = 1
    VERSION_ID = 1
    ELEMENTS = {0: MainElement}
    CRPL = 32768
    PATH = "/org/example/node"

    async def run(self):
        async with self:
            await self.join()
            sleep(20)

def main():
    loop = asyncio.get_event_loop()
    app = SampleApplication(loop)
    loop.run_until_complete(app.run())

if __name__ == '__main__':
    logger.setLevel(logging.DEBUG)

    handler = logging.StreamHandler(sys.stdout)
    handler.setLevel(logging.DEBUG)
    formatter = logging.Formatter('%(levelname)s \t %(message)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)

    main()

Node output

root@raspberrypi:/home/pi# python3 mesh/main.py 
DEBUG    Using selector: EpollSelector
DEBUG    Connecting to D-Bus
INFO     Connecting to org.bluez.mesh
INFO     Registering application
Joining the network with uuid cb2ce7c3-14e6-514a-9027-5bab0182f54e
INFO     Join cb2ce7c3-14e6-514a-9027-5bab0182f54e
Traceback (most recent call last):
  File "mesh/main.py", line 47, in <module>
    main()
  File "mesh/main.py", line 35, in main
    loop.run_until_complete(app.run())
  File "/usr/lib/python3.7/asyncio/base_events.py", line 584, in run_until_complete
    return future.result()
  File "mesh/main.py", line 28, in run
    await self.join()
  File "/usr/local/lib/python3.7/dist-packages/bluetooth_mesh/application.py", line 754, in join
    return await self._join_complete
bluetooth_mesh.utils.MeshError: unexpected-error

Both programs are run at the same time, and the 20 seconds delay in the node is never expired. The connection is simply broken. However there seems to be a first message arriving, could you guide me on this?

pintify commented 4 years ago

Is there a more complete example of a provisioner and/or node than the Quickstart from the reference?

Wezzu commented 4 years ago

I'm sorry just posting here but I would also be very grateful for a complete and well-descripted example code. Is it possible, if you could share the solution with me or could you please help with the code, that you posted above? It would be really important for me and any help from you would be really appreciated! Thank you in advance for your help! Contact me: sz.andras960@gmail.com

pintify commented 4 years ago

Sorry, I'm working in a simple example for a provisioner and a node, but I've been unable so far to create a working connection, maybe the maintainer could provide some good example

pintify commented 4 years ago

My last attemp used the same node source but a more simplified provisioning:

import asyncio
import secrets
import logging
import sys
from time import sleep
from uuid import UUID
from typing import Dict
from bluetooth_mesh.application import Application, Element
from bluetooth_mesh.models import ConfigClient, ConfigServer, HealthClient, HealthServer
from bluetooth_mesh.messages.config import GATTNamespaceDescriptor
from bluetooth_mesh.crypto import ApplicationKey, DeviceKey, NetworkKey

logger = logging.getLogger()

class MainElement(Element):
    LOCATION = GATTNamespaceDescriptor.MAIN
    MODELS = [ConfigClient, ConfigServer, HealthClient]

class SampleApplication(Application):
    COMPANY_ID = 0x0136  # Silvair
    PRODUCT_ID = 1
    VERSION_ID = 1
    ELEMENTS = {0: MainElement}
    CRPL = 32768
    PATH = "/org/example/provisioner"
    CAPABILITIES = []

    @property
    def dev_key(self):
        return DeviceKey(secrets.token_bytes(16))

    @property
    def primary_net_key(self):
        return 0, NetworkKey(secrets.token_bytes(16))

    @property
    def app_keys(self):
        return {0: ApplicationKey(secrets.token_bytes(16))}

    def scan_result(self, rssi: int, data: bytes, options: dict):
        logger.info("Detected node with RSSI %s" % rssi)
        logger.info("Node has data %s" % data)
        logger.info("Node has options %s" % options)

    def add_node_complete(self, uuid: bytes, unicast: int, count: int):
        logger.info("Connected %s (%s / %s)" % (uuid, unicast, count))

    def add_node_failed(self, uuid: bytes, reason: str):
        logger.info("Unable to connect to %s: %s" % (uuid, reason))

    def request_prov_data(self, count: int):
        logger.info("Request prov data called with count %s" % count)
        return (0, count + 1)

    async def configure_remote(self):
        client = self.elements[0][ConfigClient]

        status = await client.add_app_key(
            2, net_index=0,
            app_key_index=0,
            net_key_index=0,
            app_key=self.app_keys[0]
        )

        logger.info("App Key added")

        assert status == StatusCode.SUCCESS, \
            'Cannot add application key: %s' % status

        status = await client.bind_app_key(
            2, net_index=0,
            element_address=2,
            app_key_index=0,
            model=HealthServer
        )

        assert status == StatusCode.SUCCESS, \
            'Cannot bind application key: %s' % status

        logger.info("Configured remote device")

    async def run(self):
        async with self:
            config = await self.connect(1)
            await self.management_interface.add_node(UUID('{cb2ce7c3-14e6-514a-9027-5bab0182f54e}'))
            logger.info("Little wait for the connection to succeed")
            sleep(15)
            logger.info("Configuring remote node...")
            try:
                await self.configure_remote()
            except Exception as ex:
                logger.error("Error received: %s", ex)
            logger.info("Little wait for the configuration")
            sleep(10)
            logger.info("Node added?")

            client = self.elements[0][HealthClient]
            while True:
                await client.attention(0x0002, app_index=0, attention=3)

def main():
    loop = asyncio.get_event_loop()
    app = SampleApplication(loop)
    loop.run_until_complete(app.run())

if __name__ == '__main__':
    logger.setLevel(logging.DEBUG)

    handler = logging.StreamHandler(sys.stdout)
    handler.setLevel(logging.DEBUG)
    formatter = logging.Formatter('%(levelname)s \t %(message)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)

    main()

However, there seems to be a lost message, the request_prov_data is not properly recovered from the dbus. The output of the log is:

DEBUG    Using selector: EpollSelector
DEBUG    Connecting to D-Bus
INFO     Connecting to org.bluez.mesh
INFO     Registering application
INFO     Attach 8f292b02309cf66c (socket_pair=False, socket_path=None)
ERROR    Attach failed: Attach failed, trying to import node
WARNING      Import 08ff2811-1446-59aa-859b-b0546d2f403f
INFO     Attach 215a67d6f838118a (socket_pair=False, socket_path=None)
INFO     Attached to node /org/bluez/mesh/node08ff2811144659aa859bb0546d2f403f, address: 0001, configuration: defaultdict(<class 'dict'>, {})
INFO     Little wait for the connection to succeed

INFO     Configuring remote node...
DEBUG    Sending: /org/example/provisioner/element0 -> 0002 [remote True, net_index 0] ConfigOpcode.APPKEY_ADD Container(app_key_index=0, net_key_index=0, app_key=b'8\x96\x84\xf3s\xcd\xf8\xd7cO\xa3Zy\xee\xba\n')
DEBUG    Sending: /org/example/provisioner/element0 - > 0001 [remote 2, net_index 0] 00000000389684f373cdf8d7634fa35a79eeba0a
INFO     Request prov data called with count 1
ERROR    got unexpected error processing a message: Expected function to return a list of arguments.
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/dbus_next/message_bus.py", line 545, in _on_message
    self._process_message(msg)
  File "/usr/local/lib/python3.7/dist-packages/dbus_next/message_bus.py", line 625, in _process_message
    handler(msg, send_reply)
  File "/usr/local/lib/python3.7/dist-packages/dbus_next/message_bus.py", line 645, in handler
    body = ServiceInterface._fn_result_to_body(result, method.out_signature_tree)
  File "/usr/local/lib/python3.7/dist-packages/dbus_next/service.py", line 443, in _fn_result_to_body
    raise SignatureBodyMismatchError('Expected function to return a list of arguments')
dbus_next.errors.SignatureBodyMismatchError: Expected function to return a list of arguments

ERROR    Error received: method_fn() got an unexpected keyword argument 'flags'
INFO     Little wait for the configuration
INFO     Node added?
DEBUG    Sending: /org/example/provisioner/element0 -> 0002 [app_index 0] HealthOpcode.ATTENTION_SET Container(attention=3)
DEBUG    Sending: /org/example/provisioner/element0 -> 0002 [app_index 0] 800503
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/bluetooth_mesh/models/base.py", line 387, in query
    await asyncio.wait_for(status, timeout=timeout)
  File "/usr/lib/python3.7/asyncio/tasks.py", line 423, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

While the dbus console shows:

...
method return time=1598522841.196463 sender=:1.251 -> destination=:1.252 serial=19 reply_serial=29
method call time=1598522849.744035 sender=:1.251 -> destination=:1.252 serial=20 path=/org/example/provisioner; interface=org.bluez.mesh.Provisioner1; member=RequestProvData
   byte 1

As shown, the RequestProvData is called at the moment of the management_interface.add_node, in dbus, however, the python source doesn't executes the method request_prov_data until long after that moment, when the configuration is being done. Due to this problem, the node ends up with a JoinFailed as shown by its dbus monitor:

method call time=1598523029.178636 sender=:1.160 -> destination=:1.190 serial=44 path=/org/example/node; interface=org.bluez.mesh.Application1; member=JoinFailed
   string "bad-pdu"
signal time=1598523029.183112 sender=org.freedesktop.DBus -> destination=:1.190 serial=6 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.190"
signal time=1598523029.183210 sender=org.freedesktop.DBus -> destination=(null destination) serial=69 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.190"
   string ":1.190"
   string ""

SilvairGit / python-bluetooth-mesh