Invalid Tag exceptions while polling

[gnmerritt]

I'm using bacpypes (version 0.18.4) via BAC0 (version 21.02.25) to poll sensor data in a number of buildings. In one particular building I am getting intermittent exceptions in the bacpypes polling threads that look related to decoding a response. These three traces all seem to happen 1-2 times per day at relatively random intervals. It appears that things continue to work (e.g. I am seeing data from all the points I expect to) but figured I'd report these traces in case helpful.

I realize that these exceptions aren't terrible useful in finding the problem, so if there's a particular bacpypes debugger I can turn on to help glean some more info I'm happy to do so. Please just let me know.

Traceback (most recent call last):
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/appservice.py", line 1530, in confirmation
   xpdu.decode(apdu)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/apdu.py", line 712, in decode
   Sequence.decode(self, self._tag_list)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 185, in decode
   helper.decode(taglist)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 482, in decode
   value.decode(taglist)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 176, in decode
   raise MissingRequiredParameter("%s expected opening tag %d" % (element.name, element.context))
bacpypes.errors.MissingRequiredParameter: listOfResults expected opening tag 1
complex ack decoding error: AttributeError("'NoneType' object has no attribute 'tagClass'")

Traceback (most recent call last):
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/appservice.py", line 1530, in confirmation
   xpdu.decode(apdu)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/apdu.py", line 712, in decode
   Sequence.decode(self, self._tag_list)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 185, in decode
   helper.decode(taglist)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 482, in decode
   value.decode(taglist)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 185, in decode
   helper.decode(taglist)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 482, in decode
   value.decode(taglist)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 224, in decode
   raise InvalidTag("%s expected context tag %d" % (element.name, element.context))
bacpypes.errors.InvalidTag: propertyIdentifier expected context tag 2
complex ack decoding error: MissingRequiredParameter('listOfResults expected opening tag 1')

Traceback (most recent call last):
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/appservice.py", line 1530, in confirmation
   xpdu.decode(apdu)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/apdu.py", line 712, in decode
   Sequence.decode(self, self._tag_list)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 185, in decode
   helper.decode(taglist)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 482, in decode
   value.decode(taglist)
 File "/usr/local/lib/python3.8/dist-packages/bacpypes/constructeddata.py", line 176, in decode
   raise MissingRequiredParameter("%s expected opening tag %d" % (element.name, element.context))
bacpypes.errors.MissingRequiredParameter: listOfResults expected opening tag 1
complex ack decoding error: InvalidTag('propertyIdentifier expected context tag 2')

[JoelBender]

In the second case the incoming ReadPropertyMultipleACK has an object identifier, the first element of the ReadAccessResult, but the packet is clipped at that point and there is no ReadAccessResultElement following it (missing opening tag for the list). In the third case, the opening tag is there but the the property identifier of the ReadAccessResultElement is missing, etc.

It could be (a) that the packet is clipped in transit, but that would be very unusual, (b) the server device you are reading the content from hasn't generated the entire APDU so it should be segmented with more to follow, or (c-1) the device said the response was segmented but BACpypes didn't pick up on the problem or (c-2) there's some other bug.

If you can run daemonlogger on the client and stream the packets to a rolling log file (maybe split every hour?) and line up the error timestamps with the capture contents, at some point you'll find out the actual packet with the problem. The BACpypes-pcap utilities use the same decoder(s). Setting up the filters to only capture RPM-ACK messages will help keep the file sizes manageable.

[gnmerritt]

Ok, so I gave this a shot on two different hosts that are intermittently logging the errors

Setup

$ cat filter.bpf 
dst port 47808 && dst host 10.3.31.243

$ sudo daemonlogger -t 1h -i ens33 -f filter.bp

Which has me with a whole bunch of pcap files e.g. daemonlogger.pcap.1623859245

Error reproduction attempt

To try and reproduce, I fed the files to a slightly edited ReadPropertySummaryFilter.py

@@ -17,7 +17,10 @@ from bacpypes.consolelogging import ArgumentParser

 from bacpypes.pdu import Address
 from bacpypes.analysis import trace, strftimestamp, Tracer
-from bacpypes.apdu import ReadPropertyRequest, ReadPropertyACK
+from bacpypes.apdu import (
+    ReadPropertyRequest, ReadPropertyACK,
+    ReadPropertyMultipleRequest, ReadPropertyMultipleACK
+)

 # some debugging
 _debug = 0
@@ -138,7 +141,7 @@ class ReadPropertySummary(Tracer):
                 return

         # check for reads
-        if isinstance(pkt, ReadPropertyRequest):
+        if isinstance(pkt, ReadPropertyRequest) or isinstance(pkt, ReadPropertyMultipleRequest):
             key = (pkt.pduSource, pkt.pduDestination, pkt.apduInvokeID)
             if key in requests:
                 if _debug:
@@ -152,7 +155,7 @@ class ReadPropertySummary(Tracer):
                 traffic.append(msg)

         # now check for results
-        elif isinstance(pkt, ReadPropertyACK):
+        elif isinstance(pkt, ReadPropertyACK) or isinstance(pkt, ReadPropertyMultipleACK):
             key = (pkt.pduDestination, pkt.pduSource, pkt.apduInvokeID)
             req = requests.get(key, None)
             if req:

$ find ... -name "*pcap*" | xargs -n10 -P16 python3 ~/sources/bacpypes-pcap/ReadPropertySummaryFilter.py 

This chugs along for a couple minutes and doesn't print anything. Since my BPF is only looking at packets addressed to my box I'm not surprised to see an empty stdout - there are no outgoing requests for the script to match against and then print.

But, I was expecting the same decoding errors + exception stack traces to happen since the RPMAck objects are getting created. I left the packet capture running for a couple days and we definitely saw errors in both buildings over that period.

Any thoughts? Thanks in advance!

[zoopp]

I recall seeing this packet 'clipping' behavior in the past when sending datagrams of a size that was greater than the underlying MTU of the IP network (typically this is 1500 bytes, but not always). Unfortunately I don't recall the exact details as this was quite a while ago but I do recall that the way I worked around it was to pin the max apdu length to 1024 bytes.

This might not help and it might have been a totally different issue but I thought I should mention it.

[gnmerritt]

thanks @zoopp - I'll give that a try