JoelBender / BACpypes3

BACnet communications library
33 stars 7 forks source link

BACnet write priority not showing up when checked #12

Closed bbartling closed 8 months ago

bbartling commented 9 months ago

Hi Joel,

Would you have a tip on how to troubleshoot when I run this script in the gist link below on a rasp pi python 3.9 BACnet write to a test bench MSTP device it works: https://gist.github.com/bbartling/573030a2facc97e178b2362606b9cdda#file-write-property-py

$ python write-property.py --debug
DEBUG:__main__:args: Namespace(loggers=False, debug=[], color=None, route_aware=None, name='Excelsior', instance=999, network=0, address=None, vendoridentifier=999, foreign=None, ttl=30, bbmd=None)
DEBUG:__main__:device_address: <RemoteStation 12345:2>
DEBUG:__main__:object_identifier: (<ObjectType: analog-value>, 301)
DEBUG:__main__:priority: 10
DEBUG:__main__:app: <bacpypes3.app.Application object at 0x75c0d340>
DEBUG:__main__:response: None

The device accepts the value but nothing shows up on priority 10 when I check it from a Windows OS on the same test bench LAN. image

JoelBender commented 9 months ago

Can you please confirm that the 192.168.0.190 is responding as the router to network 12345? You should see UDP traffic between your test device (TD) and the router, Who-Is-Router-To-Network going out, I-Am-Router-To-Network coming back, the WritePropertyRequest with the NPCI showing DNET/DLEN/DADR with the values (12345, 1, 2), and the simple ack coming back with the same SNET/SLEN/SADR content.

If you get an ack back and don't see the value, there's an issue with the device you are talking to (called the Implementation Under Test, IUT).

bbartling commented 9 months ago

Hi Joel,

Am I close at all with this code? Any tips greatly appreciated... this is also pushing my understanding of BACnet and great learning experience for me so thanks for any tips!! and patience... am trying to confirm that the 192.168.0.190 is responding as the router to network 12345...

import asyncio
from bacpypes3.debugging import ModuleLogger
from bacpypes3.app import Application
from bacpypes3.pdu import Address
from bacpypes3.primitivedata import ObjectIdentifier
from bacpypes3.apdu import IAmRequest, WritePropertyRequest, SimpleAckPDU
from bacpypes3.argparse import SimpleArgumentParser
from bacpypes3.service.device import WhoIsIAmServices, WhoHasIHaveServices

_debug = 0
_log = ModuleLogger(globals())

ROUTER = "192.168.0.190"
MSTP_NETWORK = 12345

async def main():
    app = None
    try:
        parser = SimpleArgumentParser()
        args = parser.parse_args()

        if _debug:
            _log.debug("args: %r", args)

        app = Application.from_args(args)
        if _debug:
            _log.debug("app: %r", app)

        # Initialize the WhoIsIAmServices
        who_is_service = WhoIsIAmServices()

        # Perform a Who-Is-Router-To-Network request to confirm the router
        who_is_future = await who_is_service.who_is(
            low_limit=1,
            high_limit=5000,  
            address=Address(ROUTER), # Address("*") for broadcast
            timeout=10,
        )

        # Handle the results of the Who-Is-Router-To-Network request
        who_is_results = await who_is_future
        if who_is_results:
            _log.debug("Router Found:", who_is_results)
        else:
            _log.debug("Router Not Found")

    finally:
        if app:
            app.close()

if __name__ == "__main__":
    asyncio.run(main())

This will throw an error:

$ python router-test.py 
Exception in callback IPv4DatagramServer.set_broadcast_transport_protocol(<IPv4Address 192.168.0.101>)(<Task cancell...ents.py:1240>>)
handle: <Handle IPv4DatagramServer.set_broadcast_transport_protocol(<IPv4Address 192.168.0.101>)(<Task cancell...ents.py:1240>>)>
Traceback (most recent call last):
  File "/home/bbartling/junk/router-test.py", line 35, in main
    who_is_future = await who_is_service.who_is(
  File "/home/bbartling/.local/lib/python3.9/site-packages/bacpypes3/service/device.py", line 225, in who_is
    self.request(who_is)
AttributeError: 'WhoIsIAmServices' object has no attribute 'request'

And another exceptions related to: AttributeError: 'IPv4DatagramServer' object has no attribute 'local_transport'

JoelBender commented 9 months ago

Nope, not close this time :-). WhoIsIAmServices is called a "mix-in class" which means it by itself doesn't provide the basic functionality that is needed, in this case sending and receiving PDUs at the application layer, but adds additional methods and functions, in this case device-address-binding. If you look and the Application definition you'll notice that it inherits from lots of different groups of services, each focuses on some specific methods. So your app instance already has the who_is() method, call it like app.who_is().

The other piece is that this call who_is_future = await app.who_is(...) you are almost correct in that the who_is() method returns a future, and you are awaiting it to complete, so the result will be a list of I-Am responses like this. You do not need to then await that, it's already a list!

The next problem is that the I-Am responses that you get will be from the router application layer, not it's network layer. So even though you might think it's a router, it might be just a normal device that has a device instance number between 1 and 5000. There are two ways to handle this (1) do a global broadcast request for a device on the MSTP network, or (2) generate a local broadcast Who-Is-Router-To-Network and given that network layer service the 12345 requested network.

The response from (1) will have a source address that looks like 12345:nn which means the network layer stuff is happy and you can prowl around the network layer datastructures and see how it's done.

The code for (2) is here, note that the application has a network service element instance called nse where the who_is_router_to_network() method is defined.

If you can also run python3 -m bacpypes3 --debug bacpypes3.netservice --color and watch what is happening at the network layer when you enter wirtn *:* 12345, or even when you enter whois *:* 1 5000.

bbartling commented 9 months ago

Wow cool, thanks.. so whois *:* 1 5000 is No response(s)

Here's the full traceback and if you dont mind me asking what all goes on in this process?

$ python3 -m bacpypes3 --debug bacpypes3.netservice --color
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:__init__ sap=None sid=None
DEBUG:bacpypes3.netservice.RouterInfoCache:__init__
DEBUG:bacpypes3.netservice.NetworkServiceElement:__init__ eid=None
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:bind <bacpypes3.ipv4.link.NormalLinkLayer object at 0x75b8e250> net=None address=<IPv4Address 192.168.0.101>
DEBUG:bacpypes3.netservice.NetworkAdapter:__init__ <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8> None <IPv4Address 192.168.0.101> cid=None
    <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
        adapters = {}
        router_info_cache = <bacpypes3.netservice.RouterInfoCache object at 0x75b8ea90>
            routers = {}
            path_info = {}
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - adapter: None, <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
    <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
        adapterSAP = <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
        adapterAddr = <IPv4Address 192.168.0.101>
        adapterNetConfigured = 0
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - setting local adapter
> wirtn *:* 12345
DEBUG:bacpypes3.netservice.NetworkServiceElement:who_is_router_to_network None <GlobalBroadcast *:*> 12345
DEBUG:bacpypes3.netservice.NetworkServiceElement:    - sap: <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
    <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
        adapters = {
            None : <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
                adapterSAP = <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
                adapterAddr = <IPv4Address 192.168.0.101>
                adapterNetConfigured = 0
            }
        local_adapter = <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
        router_info_cache = <bacpypes3.netservice.RouterInfoCache object at 0x75b8ea90>
            routers = {}
            path_info = {}
DEBUG:bacpypes3.netservice.WhoIsRouterToNetworkFuture:__init__ <bacpypes3.netservice.NetworkServiceElement object at 0x75b8eac0> None <GlobalBroadcast *:*> 12345
    <bacpypes3.netservice.NetworkServiceElement object at 0x75b8eac0>
        who_is_router_to_network_futures = []
        what_is_network_number_resolution = {}
DEBUG:bacpypes3.netservice.WhoIsRouterToNetworkFuture:    - future: <Future pending cb=[WhoIsRouterToNetworkFuture.who_is_router_to_network_done()]>
DEBUG:bacpypes3.netservice.WhoIsRouterToNetworkFuture:    - loop time: 782192.497655395
DEBUG:bacpypes3.netservice.WhoIsRouterToNetworkFuture:    - _timeout_handle: <TimerHandle when=782194.498636027 WhoIsRouterToNetworkFuture.who_is_router_to_network_timeout()>
DEBUG:bacpypes3.netservice.NetworkServiceElement:    - npdu: <bacpypes3.npdu.WhoIsRouterToNetwork object at 0x75b8ed60>
    <bacpypes3.npdu.WhoIsRouterToNetwork object at 0x75b8ed60>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        npduVersion = 1
        npduDADR = <GlobalBroadcast *:*>
        npduHopCount = 255
        npduNetMessage = 0
        wirtnNetwork = 12345
        pduData = x''
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:sap_indication <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18> <bacpypes3.npdu.WhoIsRouterToNetwork object at 0x75b8ed60>
    <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
        adapterSAP = <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
        adapterAddr = <IPv4Address 192.168.0.101>
        adapterNetConfigured = 0
    <bacpypes3.npdu.WhoIsRouterToNetwork object at 0x75b8ed60>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        npduVersion = 1
        npduDADR = <GlobalBroadcast *:*>
        npduHopCount = 255
        npduNetMessage = 0
        wirtnNetwork = 12345
        pduData = x''
DEBUG:bacpypes3.netservice.NetworkAdapter:process_npdu <bacpypes3.npdu.WhoIsRouterToNetwork object at 0x75b8ed60> (net=None)
    <bacpypes3.npdu.WhoIsRouterToNetwork object at 0x75b8ed60>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        npduVersion = 1
        npduDADR = <GlobalBroadcast *:*>
        npduHopCount = 255
        npduNetMessage = 0
        wirtnNetwork = 12345
        pduData = x''
DEBUG:bacpypes3.netservice.NetworkAdapter:    - pdu: <bacpypes3.pdu.PDU object at 0x75b8eef8>
    <bacpypes3.pdu.PDU object at 0x75b8eef8>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        pduData = x'01.a0.ff.ff.00.ff.00.30.39'
DEBUG:bacpypes3.netservice.NetworkAdapter:confirmation <bacpypes3.pdu.PDU object at 0x75bb61a8> (net=None)
    <bacpypes3.pdu.PDU object at 0x75bb61a8>
        pduSource = <IPv4Address 192.168.0.190>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        pduData = x'01.80.01.30.39'
DEBUG:bacpypes3.netservice.NetworkAdapter:    - npdu_class: <class 'bacpypes3.npdu.IAmRouterToNetwork'>
DEBUG:bacpypes3.netservice.NetworkAdapter:    - npdu: <bacpypes3.npdu.IAmRouterToNetwork object at 0x75bb61c0>
    <bacpypes3.npdu.IAmRouterToNetwork object at 0x75bb61c0>
        pduSource = <IPv4Address 192.168.0.190>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        npduVersion = 1
        npduControl = 128
        npduNetMessage = 1
        iartnNetworkList = [12345]
        pduData = x''
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:process_npdu <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18> <bacpypes3.npdu.IAmRouterToNetwork object at 0x75bb61c0>
    <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
        adapterSAP = <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
        adapterAddr = <IPv4Address 192.168.0.101>
        adapterNetConfigured = 0
    <bacpypes3.npdu.IAmRouterToNetwork object at 0x75bb61c0>
        pduSource = <IPv4Address 192.168.0.190>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        npduVersion = 1
        npduControl = 128
        npduNetMessage = 1
        iartnNetworkList = [12345]
        pduData = x''
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - nse: <bacpypes3.netservice.NetworkServiceElement object at 0x75b8eac0>
    <bacpypes3.netservice.NetworkServiceElement object at 0x75b8eac0>
        who_is_router_to_network_futures = [<bacpypes3.netservice.WhoIsRouterToNetworkFuture object at 0x75b8ef70>]
        what_is_network_number_resolution = {}
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - no DADR
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - processLocally: True
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - forwardMessage: False
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - network layer message
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - processing NPDU locally
DEBUG:bacpypes3.netservice.NetworkServiceElement:indication <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18> <bacpypes3.npdu.IAmRouterToNetwork object at 0x75bb61c0>
    <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
        adapterSAP = <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
        adapterAddr = <IPv4Address 192.168.0.101>
        adapterNetConfigured = 0
    <bacpypes3.npdu.IAmRouterToNetwork object at 0x75bb61c0>
        pduSource = <IPv4Address 192.168.0.190>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        npduVersion = 1
        npduControl = 128
        npduNetMessage = 1
        iartnNetworkList = [12345]
        pduData = x''
DEBUG:bacpypes3.netservice.NetworkServiceElement:IAmRouterToNetwork <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18> <bacpypes3.npdu.IAmRouterToNetwork object at 0x75bb61c0>
    <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
        adapterSAP = <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
        adapterAddr = <IPv4Address 192.168.0.101>
        adapterNetConfigured = 0
    <bacpypes3.npdu.IAmRouterToNetwork object at 0x75bb61c0>
        pduSource = <IPv4Address 192.168.0.190>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        npduVersion = 1
        npduControl = 128
        npduNetMessage = 1
        iartnNetworkList = [12345]
        pduData = x''
DEBUG:bacpypes3.netservice.NetworkServiceElement:    - sap: <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
    <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
        adapters = {
            None : <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
                adapterSAP = <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
                adapterAddr = <IPv4Address 192.168.0.101>
                adapterNetConfigured = 0
            }
        local_adapter = <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
        router_info_cache = <bacpypes3.netservice.RouterInfoCache object at 0x75b8ea90>
            routers = {}
            path_info = {}
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:update_router_references None <IPv4Address 192.168.0.190> [12345]
DEBUG:bacpypes3.netservice.RouterInfoCache:update_router_info None <IPv4Address 192.168.0.190> [12345]
DEBUG:bacpypes3.netservice.RouterInfoCache:    - add path: None -> 12345 via <IPv4Address 192.168.0.190>
DEBUG:bacpypes3.netservice.NetworkServiceElement:    - not a router
DEBUG:bacpypes3.netservice.WhoIsRouterToNetworkFuture:match <bacpypes3.npdu.IAmRouterToNetwork object at 0x75bb61c0>
    <bacpypes3.npdu.IAmRouterToNetwork object at 0x75bb61c0>
        pduSource = <IPv4Address 192.168.0.190>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        npduVersion = 1
        npduControl = 128
        npduNetMessage = 1
        iartnNetworkList = [12345]
        pduData = x''
DEBUG:bacpypes3.netservice.WhoIsRouterToNetworkFuture:    - npdu_source: <IPv4Address 192.168.0.190>
DEBUG:bacpypes3.netservice.WhoIsRouterToNetworkFuture:    - network match
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - no forwarding
DEBUG:bacpypes3.netservice.WhoIsRouterToNetworkFuture:who_is_router_to_network_done <Future finished result=[(<bacpypes3.ne...at 0x75b8ea18>, <bacpypes3.np...at 0x75bb61c0>)]>
192.168.0.190
    12345
> whois *:* 1 5000
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:indication <bacpypes3.pdu.PDU object at 0x75b8e100>
    <bacpypes3.pdu.PDU object at 0x75b8e100>
        pduDestination = <GlobalBroadcast *:*>
        pduExpectingReply = False
        pduNetworkPriority = 0
        pduData = x'10.08.09.01.1a.13.88'
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - nse: <bacpypes3.netservice.NetworkServiceElement object at 0x75b8eac0>
    <bacpypes3.netservice.NetworkServiceElement object at 0x75b8eac0>
        who_is_router_to_network_futures = []
        what_is_network_number_resolution = {}
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - local_adapter: <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
    <bacpypes3.netservice.NetworkAdapter object at 0x75b8ea18>
        adapterSAP = <bacpypes3.netservice.NetworkServiceAccessPoint object at 0x75b8ead8>
        adapterAddr = <IPv4Address 192.168.0.101>
        adapterNetConfigured = 0
DEBUG:bacpypes3.netservice.NetworkServiceAccessPoint:    - npdu: <bacpypes3.npdu.NPDU object at 0x75bb61a8>
    <bacpypes3.npdu.NPDU object at 0x75bb61a8>
        pduDestination = <GlobalBroadcast *:*>
        pduExpectingReply = False
        pduNetworkPriority = 0
        npduVersion = 1
        pduData = x'10.08.09.01.1a.13.88'
DEBUG:bacpypes3.netservice.NetworkAdapter:process_npdu <bacpypes3.npdu.NPDU object at 0x75bb61a8> (net=None)
    <bacpypes3.npdu.NPDU object at 0x75bb61a8>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        npduVersion = 1
        npduDADR = <GlobalBroadcast *:*>
        npduHopCount = 255
        pduData = x'10.08.09.01.1a.13.88'
DEBUG:bacpypes3.netservice.NetworkAdapter:    - pdu: <bacpypes3.pdu.PDU object at 0x75bb6280>
    <bacpypes3.pdu.PDU object at 0x75bb6280>
        pduDestination = <LocalBroadcast *>
        pduExpectingReply = False
        pduNetworkPriority = 0
        pduData = x'01.20.ff.ff.00.ff.10.08.09.01.1a.13.88'
No response(s)
JoelBender commented 9 months ago

I created a gist with your output so I can link to it:

There are no devices with a device identifier in that range, try again without specifying a low limit and high limit and see who responds. This seems to be an application layer problem, so cut down the volume of debug output and switch to debugging that service --debug bacpypes3.service.device.WhoIsIAmServices.

bbartling commented 9 months ago

out curiosity would these troubleshooting commands also work on legacy bacpypes? Something like:

$ python3 -m bacpypes --debug bacpypes.netservice
> wirtn *:* 12345
> whois *:* 1 5000

$ python3 -m bacpypes --debug bacpypes.service.device.WhoIsIAmServices
JoelBender commented 9 months ago

Yes, the same pattern applies, each module in the package directory has a logging hook, and each class in each module does as well. The module organization is a little different, the option to get a list of logging objects has changed from --buggers to --loggers.