WhoIsIAm.py in 17.8 doesn't print anything

[epaulson]

In 0.17.8. WhoIsIAm.py doesn't print any results, though --debug shows that network traffic is getting there. This worked on 0.17.7.

On a test network with 1 device:

(bacpypes) MBP18:samples cpaulser$ python
Python 3.8.1 (default, Jan  8 2020, 16:15:59) 
[Clang 4.0.1 (tags/RELEASE_401/final)] :: Anaconda, Inc. on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import bacpypes
>>> bacpypes.__version__
'0.18.0'
>>> 
(bacpypes) MBP18:samples cpaulser$ python WhoIsIAm.py --ini ../../config.ini 
> whois
> Exiting...
(bacpypes) MBP18:samples cpaulser$ python WhoIsIAm.py --ini ../../config.ini --debug
DEBUG:__main__:initialization
DEBUG:__main__:    - args: Namespace(buggers=False, color=None, debug=[], ini={'objectname': 'MBPMac', 'address': '192.168.56.1/24', 'objectidentifier': '101', 'maxapdulengthaccepted': '1024', 'segmentationsupported': 'segmentedBoth', 'vendoridentifier': '15'}, route_aware=None)
DEBUG:__main__:    - this_device: <bacpypes.local.device.LocalDeviceObject object at 0x7fa1f83cea00>
DEBUG:__main__.WhoIsIAmApplication:__init__ (<bacpypes.local.device.LocalDeviceObject object at 0x7fa1f83cea00>, '192.168.56.1/24')
DEBUG:__main__:    - this_application: <__main__.WhoIsIAmApplication object at 0x7fa1f83dc280>
DEBUG:__main__:    - this_console: <WhoIsIAmConsoleCmd(ConsoleCmd, started 123145435889664)>
DEBUG:__main__:running
> whois
DEBUG:__main__.WhoIsIAmConsoleCmd:do_whois []
DEBUG:__main__.WhoIsIAmConsoleCmd:    - request: <bacpypes.apdu.WhoIsRequest(8) instance at 0x7fa1f83dcd00>
    <bacpypes.apdu.WhoIsRequest(8) instance at 0x7fa1f83dcd00>
        pduDestination = <GlobalBroadcast *:*>
        pduExpectingReply = 0
        pduNetworkPriority = 0
        apduType = 1
        apduService = 8
        pduData = x''
DEBUG:__main__.WhoIsIAmConsoleCmd:    - iocb: <bacpypes.iocb.IOCB(1) instance at 0x7fa1f83dce50>
    <bacpypes.iocb.IOCB(1) instance at 0x7fa1f83dce50>
        args = (<bacpypes.apdu.WhoIsRequest(8) instance at 0x7fa1f83dcd00>,)
        kwargs = {}
        ioState = 0
        ioComplete = <threading.Event object at 0x7fa1f83dce80>
        ioCallback = []
        ioPriority = 0
> DEBUG:__main__.WhoIsIAmApplication:indication <bacpypes.apdu.IAmRequest(0) instance at 0x7fa1e8098190>
    <bacpypes.apdu.IAmRequest(0) instance at 0x7fa1e8098190>
        pduSource = <Address 192.168.56.101>
        pduDestination = <Address 192.168.56.1>
        pduExpectingReply = False
        pduNetworkPriority = 0
        apduType = 1
        apduService = 0
        iAmDeviceIdentifier = ('device', 599)
        maxAPDULengthAccepted = 1024
        segmentationSupported = 'segmentedBoth'
        vendorID = 15
        pduData = x''
Exiting...
DEBUG:__main__:fini
(bacpypes) MBP18:samples cpaulser$ 

With 0.17.7 on the same machine, in a different window and different python enviroment:

(bacpypes177) MBP18:samples cpaulser$ python 
Python 3.8.1 (default, Jan  8 2020, 16:15:59) 
[Clang 4.0.1 (tags/RELEASE_401/final)] :: Anaconda, Inc. on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import bacpypes
>>> bacpypes.__version__
'0.17.7'
>>> 
(bacpypes177) MBP18:samples cpaulser$ python WhoIsIAm.py --ini ../../config.ini 
> whois
> pduSource = <Address 192.168.56.101>
iAmDeviceIdentifier = ('device', 599)
maxAPDULengthAccepted = 1024
segmentationSupported = segmentedBoth
vendorID = 15
Exiting...
(bacpypes177) MBP18:samples cpaulser$ 

[JoelBender]

Could you please run these tests again and include --debug __main__ bacpypes.core in both versions? There might be an exception that is caught in the "catch all" in the run() function that would explain the difference.

[JoelBender]

Ah, I think I know what's happening. I put a guard in ApplicationIOController.request() to make sure that it is not accidentally called with confirmed services, and then more stuff in ApplicationIOController.process_io() to make it work correctly. But _app_request() bypasses the guard, which also means that WhoIsIAmApplication.request() never gets called because it appears before Application.request() in the MRO chain.

So for the WhoIsIAmApplication application to keep track of the request so it can line up responses, it need to keep a reference to it from earlier in the call sequence. I created a new branch 321-whois-iam-not-printing for this issue.

[epaulson]

Thank you. I checked out and installed that branch and re-ran the WhoIsIAm application and I saw the output I was expecting.Bacpypes.__version__ says it is 0.18.1

The only thing that I'm not sure I'm following is that I ran it with --debug __main__.WhoIsIAmApplication __main__ bacpypes.core but I never saw a line that looks like it corresponds to

def process_io(self, iocb):
        if _debug: WhoIsIAmApplication._debug("process_io %r", iocb)

[JoelBender]

The version string you are getting is because the branch is from stage which is where stuff gets merged before released.

Try turning off the other debugging pieces leaving just the __main__.WhoIsIAmApplication and it will be easier to see, and if you turn on --color each debugging piece will get its own color, which is handy.

[epaulson]

Thanks. The output from process_io was in there, I just missed it. (I knew I shouldn't have trusted my eyes and cut&pasted it to do a proper search)

Again on this branch I see the output I was expecting. I can close this issue or I can leave it for you to close depending on how you want to handle the merge etc.

Thanks!

[JoelBender]

Don't forget that you can say --debug __main__:snork.txt and the debugging output will go to the text file rather than stderr.

[epaulson]

BTW, this is still happening for me. On Ubuntu 20.04 in a VM, using BACpypes installed with pip:

(bptest-s) erik@erik-u20b:~/development/bacpypes/bacpypes$ python
Python 3.9.7 (default, Sep 16 2021, 13:09:58) 
[GCC 7.5.0] :: Anaconda, Inc. on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import bacpypes
>>> bacpypes.__version__
'0.18.5'
>>> 

(bptest-s) erik@erik-u20b:~/development/bacpypes/bacpypes$ python samples/WhoIsIAm.py --debug __main__ bacpypes.core
DEBUG:__main__:initialization
DEBUG:__main__:    - args: Namespace(buggers=False, debug=['__main__', 'bacpypes.core'], color=None, route_aware=None, ini={'objectname': 'WeatherServer', 'address': '10.0.2.7/24', 'objectidentifier': '599', 'maxapdulengthaccepted': '1024', 'segmentationsupported': 'segmentedBoth', 'vendoridentifier': '15', 'foreignbbmd': '128.253.109.254', 'foreignttl': '30'})
DEBUG:__main__.WhoIsIAmApplication:__init__ (<bacpypes.local.device.LocalDeviceObject object at 0x7f7699536b50>, '10.0.2.7/24')
DEBUG:bacpypes.core.deferred:deferred <bound method NetworkServiceElement.startup of <bacpypes.netservice.NetworkServiceElement object at 0x7f7698ccf520>> () {}
DEBUG:__main__:    - this_console: <WhoIsIAmConsoleCmd(ConsoleCmd, started 140147345487616)>
DEBUG:bacpypes.core.enable_sleeping:enable_sleeping 0.001
DEBUG:__main__:running
DEBUG:bacpypes.core.run:run spin=1.0 sigterm=<function stop at 0x7f76995a9c10>, sigusr1=<function print_stack at 0x7f76994bc280>
> DEBUG:bacpypes.core.deferred:deferred <bound method UDPDirector._response of <bacpypes.udp.UDPDirector 10.0.2.255:47808 at 0x7f7698ccf640>> (<bacpypes.comm.PDU object at 0x7f7698ccff10>,) {}
DEBUG:bacpypes.core.deferred:    - trigger
DEBUG:__main__.WhoIsIAmApplication:indication <bacpypes.apdu.WhoIsRequest(8) instance at 0x7f7698c9f070>
    <bacpypes.apdu.WhoIsRequest(8) instance at 0x7f7698c9f070>
        pduSource = <Address 10.0.2.8>
        pduDestination = <GlobalBroadcast *:*>
        pduExpectingReply = False
        pduNetworkPriority = 0
        apduType = 1
        apduService = 8
        pduData = x''
Exiting...
DEBUG:bacpypes.core.deferred:deferred <function stop at 0x7f76995a9c10> () {}
DEBUG:bacpypes.core.deferred:    - trigger
DEBUG:bacpypes.core.deferred:deferred <function stop at 0x7f76995a9c10> () {}
DEBUG:bacpypes.core.deferred:    - trigger
DEBUG:bacpypes.core.stop:stop
DEBUG:bacpypes.core.stop:    - trigger
DEBUG:bacpypes.core.stop:stop
DEBUG:bacpypes.core.stop:    - trigger
DEBUG:__main__:fini

[JoelBender]

This should be solved now, please install v0.18.6 I just released. The fix includes a new any command which just prints out I-Am's that are received without having to generate a Who-Is first, better for really busy networks where there's more than enough traffic without generating more.