queued messages never go out sometimes

[hemna]

hey thanks for the update for version 0.0.11.

I'm seeing some weird behavior at times. I am connecting to direwolf over tcpkiss and there are times when I send a message to aioax25, and I the debugging output shows that the packet is added to the send queue. Then it never goes out When I then send a message to direwolf from my radio, kiss gets that message and then sends it to aprsd, and then I see the queued up messages in aioax25 go out to direwolf and then out to RF finally.

Is there some reason you can think of that the messages get stuck in the queue and don't go to direwolf?

09/25/2022 08:09:42 PM TXPKT-3-hey f        DEBUG    Send 'b':WB4BOR   :hey from webchat{3'' TO KISS                                                       kiss.py:147
09/25/2022 08:09:42 PM TXPKT-3-hey f        INFO     Sending WB4BOR-12>WB4BOR,WIDE1-1,WIDE2-1: PID=0xf0 Payload=b':WB4BOR   :hey from webchat{3'           aprs.py:330
09/25/2022 08:09:42 PM TXPKT-3-hey f        DEBUG    Adding to queue: WB4BOR-12>WB4BOR,WIDE1-1,WIDE2-1: PID=0xf0 Payload=b':WB4BOR   :hey from         interface.py:62
                                                     webchat{3'

then 2 minutes later since aprsd didn't get an ack, it sends it again. It doesn't actually go out to direwolf and RF until direwolf gets a packet from RF to kiss to aprsd.

[hemna]

Digging a bit more and adding some debug statements into interface.py It looks like interface.py:_tx_next isn't getting called. I added a debug statement at the top of _tx_next and it's not getting printed out.

I wonder if this is related to asyncio looping not happening? aprsd isn't asyncio at all, except for it's usage of aioax25.

09/25/2022 08:58:22 PM TXPKT-2-chewb        DEBUG    Send 'b':WB4BOR   :chewbacca{2'' TO KISS                                                              kiss.py:147
09/25/2022 08:58:22 PM TXPKT-2-chewb        INFO     Sending WB4BOR-12>WB4BOR,WIDE1-1,WIDE2-1: PID=0xf0 Payload=b':WB4BOR   :chewbacca{2'                  aprs.py:330
09/25/2022 08:58:22 PM TXPKT-2-chewb        DEBUG    Adding to queue: WB4BOR-12>WB4BOR,WIDE1-1,WIDE2-1: PID=0xf0 Payload=b':WB4BOR   :chewbacca{2'     interface.py:62
09/25/2022 08:58:22 PM TXPKT-2-chewb        DEBUG    CTS expiry 1.4313802324678753                                                                     interface.py:64
09/25/2022 08:58:22 PM TXPKT-2-chewb        DEBUG    TX_PENDING None                                                                                   interface.py:65
09/25/2022 08:58:22 PM TXPKT-2-chewb        DEBUG    delay -7.054083347532124                                                                         interface.py:112
09/25/2022 08:58:22 PM TXPKT-2-chewb        DEBUG    Scheduling next transmission ASAP                                                                interface.py:117
09/25/2022 08:58:22 PM TXPKT-2-chewb        DEBUG    scheduling done                                                                                  interface.py:119

[hemna]

I think I might have gotten it working. I changed the line here: https://github.com/sjlongland/aioax25/blob/master/aioax25/interface.py#L114 to use call_soon_threadsafe() and that worked.

aprsd is a threaded app.

[sjlongland]

Right, didn't even think about testing thread safety… so your mileage may vary. Might be safer to pass a reference to the IOLoop running in the other thread to the aioax25 classes' constructors; and use something like:

def _do_transmit():
    interface.transmit(*args, **kwargs)
loop.call_soon_threadsafe(_do_transmit)

That at least all the aioax25 library calls have been done from the same thread.

[hemna]

can I submit a PR to change that call to call_soon_threadsafe ?

[sjlongland]

Well, we could do that… but as I say it may take more than changing one line to make the library truly thread-safe as it was written from the assumption of being used in a single-threaded asynchronous application.

If two threads called AX25Interface.send() for example, at the same time…

https://github.com/sjlongland/aioax25/blob/master/aioax25/kiss.py#L615-L620

… both will start appending their data to the same output buffer …

https://github.com/sjlongland/aioax25/blob/master/aioax25/kiss.py#L219-L233

You'll note there's no semaphores there, so it's possible two frames may be mixed up together leading to unpredictable results. It's worth noting that asyncio's Futures are not thread-safe either, and fundamentally asyncio is built on them.

The answer may to look at whether a decorator function can be applied to the methods that can be applied to the relevant methods so that if you call it from a second thread, it does something like the above to schedule the call to take place in the other thread.

[sjlongland]

https://github.com/agronholm/asyncio_extras/blob/master/asyncio_extras/threads.py#L143-L174 looks like a starting point -- not sure if I'd pull in the entire library (it hasn't been changed in years, maybe because it's unmaintained, or maybe it just hasn't needed changes), but that might be adaptable into a suitable format.