Skip to content

Instantly share code, notes, and snippets.

@sjlongland

sjlongland/teststn.log

Last active April 3, 2023 09:30
Show Gist options
  • Save sjlongland/2d59322765ae0b25d268eb55e1bc8197 to your computer and use it in GitHub Desktop.
Save sjlongland/2d59322765ae0b25d268eb55e1bc8197 to your computer and use it in GitHub Desktop.
Download ZIP
Quick and dirty test of aioax25 connected mode
Raw
teststn.log
2023-04-02 17:06:44,073 aioax25.kiss[kiss.py: 385] DEBUG OPEN new port 0
2023-04-02 17:06:44,074 aioax25.interface[router.py: 56] DEBUG Binding callsign 'VK4MSL' (regex False) SSID 4 to <bound method AX25Station._on_receive of <aioax25.station.AX25Station object at 0x7f26b28c19f0>>
2023-04-02 17:06:44,074 aioax25.kiss[kiss.py: 396] DEBUG Opening device
2023-04-02 17:06:44,074 aioax25.kiss[kiss.py: 435] DEBUG Awaiting KISS transport
2023-04-02 17:06:44,074 asyncmain[teststn.py: 59] INFO Waiting for connections
2023-04-02 17:06:44,074 aioax25.kiss[kiss.py: 488] DEBUG Delegating to KISS serial device '/dev/ax0'
2023-04-02 17:06:44,074 aioax25.kiss[kiss.py: 420] DEBUG Constructing protocol object
2023-04-02 17:06:44,075 aioax25.kiss.protocol[kiss.py: 689] DEBUG Announcing connection: SerialTransport(<_UnixSelectorEventLoop running=True closed=False debug=False>, <aioax25.kiss.KISSProtocol object at 0x7f26b28c1f60>, Serial<id=0x7f26b28c1570, open=True>(port='/dev/ax0', baudrate=9600, bytesize=8, parity='N', stopbits=1, timeout=0, xonxoff=False, rtscts=False, dsrdtr=False))
2023-04-02 17:06:50,633 aioax25.kiss[kiss.py: 223] DEBUG RECV RAW 'c000ac96689aa698e8ac96689aa698613fc0'
2023-04-02 17:06:50,634 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:06:50,634 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 17
2023-04-02 17:06:50,634 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME 00ac96689aa698e8ac96689aa698613f, REMAINING c0
2023-04-02 17:06:50,634 aioax25.kiss[kiss.py: 315] DEBUG RECV FRAME dispatch KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa698613f}
2023-04-02 17:06:50,634 aioax25.kiss.port0[kiss.py: 661] DEBUG Received frame KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa698613f}
2023-04-02 17:06:50,635 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330546.4439816863
2023-04-02 17:06:50,635 aioax25.interface[router.py: 100] DEBUG Handling incoming frame VK4MSL>VK4MSL-4*
2023-04-02 17:06:50,635 aioax25.interface[router.py: 142] DEBUG Dispatching frame to 1 receivers
2023-04-02 17:06:50,635 aioax25.station[station.py: 195] DEBUG Checking command frame sub-class: VK4MSL>VK4MSL-4*
2023-04-02 17:06:50,636 aioax25.station[station.py: 205] DEBUG Passing frame to peer VK4MSL: VK4MSL>VK4MSL-4*
2023-04-02 17:06:50,636 aioax25.station.peer.VK4MSL[peer.py: 430] DEBUG Observed 1 frame(s) via path ()
2023-04-02 17:06:50,636 aioax25.station.peer.VK4MSL[peer.py: 698] INFO Received SABM
2023-04-02 17:06:50,636 aioax25.station.peer.VK4MSL[peer.py: 857] DEBUG Initialising AX.25 2.0/2.2 mod8 connection
2023-04-02 17:06:50,636 aioax25.station.peer.VK4MSL[peer.py: 875] DEBUG Resetting the peer state
2023-04-02 17:06:50,636 aioax25.station.peer.VK4MSL[peer.py: 743] DEBUG Preparing incoming connection
2023-04-02 17:06:50,636 aioax25.station.peer.VK4MSL[peer.py: 896] INFO Connection state change: AX25PeerState.DISCONNECTED→AX25PeerState.INCOMING_CONNECTION
2023-04-02 17:06:50,637 aioax25.station.peer.VK4MSL[peer.py: 746] DEBUG Announcing incoming connection
2023-04-02 17:06:50,637 connection.VK4MSL[teststn.py: 12] INFO Incoming connection from VK4MSL
2023-04-02 17:06:50,637 aioax25.station.peer.VK4MSL[peer.py: 320] INFO Accepting incoming connection
2023-04-02 17:06:50,637 aioax25.station.peer.VK4MSL[peer.py:1274] INFO Sending UA
2023-04-02 17:06:50,637 aioax25.station.peer.VK4MSL[peer.py: 253] INFO Choosing highest rated TX/most common RX path: ()
2023-04-02 17:06:50,638 aioax25.interface[interface.py: 63] DEBUG Adding to queue: VK4MSL-4>VK4MSL
2023-04-02 17:06:50,638 aioax25.interface[interface.py: 113] DEBUG Scheduling next transmission in 0.007162549300119281
2023-04-02 17:06:50,638 aioax25.station.peer.VK4MSL[peer.py:1177] INFO Sending SABM
2023-04-02 17:06:50,638 aioax25.interface[interface.py: 63] DEBUG Adding to queue: VK4MSL-4>VK4MSL
2023-04-02 17:06:50,645 aioax25.interface[interface.py: 145] DEBUG Transmitting VK4MSL-4>VK4MSL
2023-04-02 17:06:50,645 aioax25.kiss.port0[kiss.py: 654] DEBUG XMIT AX.25 VK4MSL-4>VK4MSL
2023-04-02 17:06:50,646 aioax25.kiss[kiss.py: 238] DEBUG XMIT FRAME '00ac96689aa69860ac96689aa698e973'
2023-04-02 17:06:50,646 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330546.45769670163
2023-04-02 17:06:50,646 aioax25.interface[interface.py: 113] DEBUG Scheduling next transmission in 0.012682553613558412
2023-04-02 17:06:50,646 aioax25.kiss[kiss.py: 331] DEBUG XMIT RAW 'c000ac96689aa69860ac96689aa698e973c0'
2023-04-02 17:06:50,661 aioax25.interface[interface.py: 145] DEBUG Transmitting VK4MSL-4>VK4MSL
2023-04-02 17:06:50,661 aioax25.kiss.port0[kiss.py: 654] DEBUG XMIT AX.25 VK4MSL-4>VK4MSL
2023-04-02 17:06:50,661 aioax25.kiss[kiss.py: 238] DEBUG XMIT FRAME '00ac96689aa698e0ac96689aa698693f'
2023-04-02 17:06:50,661 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330546.4709525487
2023-04-02 17:06:50,662 aioax25.kiss[kiss.py: 331] DEBUG XMIT RAW 'c000ac96689aa698e0ac96689aa698693fc0'
2023-04-02 17:06:50,662 aioax25.kiss[kiss.py: 223] DEBUG RECV RAW 'c000ac96689aa69868ac96689aa698e173c0'
2023-04-02 17:06:50,662 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:06:50,662 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 1
2023-04-02 17:06:50,662 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME , REMAINING c000ac96689aa69868ac96689aa698e173c0
2023-04-02 17:06:50,662 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:06:50,662 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 17
2023-04-02 17:06:50,662 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME 00ac96689aa69868ac96689aa698e173, REMAINING c0
2023-04-02 17:06:50,663 aioax25.kiss[kiss.py: 315] DEBUG RECV FRAME dispatch KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa69868ac96689aa698e173}
2023-04-02 17:06:50,663 aioax25.kiss.port0[kiss.py: 661] DEBUG Received frame KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa69868ac96689aa698e173}
2023-04-02 17:06:50,663 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330546.4776626587
2023-04-02 17:06:50,663 aioax25.interface[router.py: 100] DEBUG Handling incoming frame VK4MSL*>VK4MSL-4
2023-04-02 17:06:50,663 aioax25.interface[router.py: 142] DEBUG Dispatching frame to 1 receivers
2023-04-02 17:06:50,663 aioax25.station[station.py: 205] DEBUG Passing frame to peer VK4MSL: VK4MSL*>VK4MSL-4
2023-04-02 17:06:50,663 aioax25.station.peer.VK4MSL[peer.py: 430] DEBUG Observed 2 frame(s) via path ()
2023-04-02 17:06:50,663 aioax25.station.peer.VK4MSL[peer.py: 944] INFO Received UA from peer
2023-04-02 17:06:50,663 aioax25.station.peer.VK4MSL[peer.py: 777] INFO Connection accepted by peer
2023-04-02 17:06:50,664 aioax25.station.peer.VK4MSL[peer.py: 896] INFO Connection state change: AX25PeerState.INCOMING_CONNECTION→AX25PeerState.CONNECTED
2023-04-02 17:06:50,664 connection.VK4MSL[teststn.py: 15] INFO State is now AX25PeerState.CONNECTED
2023-04-02 17:06:50,664 aioax25.station.peer.VK4MSL[peer.py:1385] DEBUG Creating new I-Frame 0
2023-04-02 17:06:50,664 aioax25.station.peer.VK4MSL[peer.py:1388] DEBUG Sending new I-Frame 0
2023-04-02 17:06:50,664 aioax25.interface[interface.py: 63] DEBUG Adding to queue: VK4MSL-4>VK4MSL: N(R)=0 P/F=False N(S)=0 PID=0xf0 Payload=b'Hello VK4MSL\r\n'
2023-04-02 17:06:50,664 aioax25.interface[interface.py: 113] DEBUG Scheduling next transmission in 0.014378678752109408
2023-04-02 17:06:50,680 aioax25.interface[interface.py: 145] DEBUG Transmitting VK4MSL-4>VK4MSL: N(R)=0 P/F=False N(S)=0 PID=0xf0 Payload=b'Hello VK4MSL\r\n'
2023-04-02 17:06:50,680 aioax25.kiss.port0[kiss.py: 654] DEBUG XMIT AX.25 VK4MSL-4>VK4MSL: N(R)=0 P/F=False N(S)=0 PID=0xf0 Payload=b'Hello VK4MSL\r\n'
2023-04-02 17:06:50,680 aioax25.kiss[kiss.py: 238] DEBUG XMIT FRAME '00ac96689aa69860ac96689aa698e900f048656c6c6f20564b344d534c0d0a'
2023-04-02 17:06:50,680 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330546.4908529266
2023-04-02 17:06:50,681 aioax25.kiss[kiss.py: 331] DEBUG XMIT RAW 'c000ac96689aa69860ac96689aa698e900f048656c6c6f20564b344d534c0d0ac0'
2023-04-02 17:06:53,734 aioax25.kiss[kiss.py: 223] DEBUG RECV RAW 'c000ac96689aa69868ac96689aa698e121c0'
2023-04-02 17:06:53,735 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:06:53,735 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 1
2023-04-02 17:06:53,735 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME , REMAINING c000ac96689aa69868ac96689aa698e121c0
2023-04-02 17:06:53,735 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:06:53,735 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 17
2023-04-02 17:06:53,736 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME 00ac96689aa69868ac96689aa698e121, REMAINING c0
2023-04-02 17:06:53,736 aioax25.kiss[kiss.py: 315] DEBUG RECV FRAME dispatch KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa69868ac96689aa698e121}
2023-04-02 17:06:53,736 aioax25.kiss.port0[kiss.py: 661] DEBUG Received frame KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa69868ac96689aa698e121}
2023-04-02 17:06:53,736 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330549.55272359535
2023-04-02 17:06:53,736 aioax25.interface[router.py: 100] DEBUG Handling incoming frame VK4MSL*>VK4MSL-4
2023-04-02 17:06:53,737 aioax25.interface[router.py: 142] DEBUG Dispatching frame to 1 receivers
2023-04-02 17:06:53,737 aioax25.station[station.py: 205] DEBUG Passing frame to peer VK4MSL: VK4MSL*>VK4MSL-4
2023-04-02 17:06:53,737 aioax25.station.peer.VK4MSL[peer.py: 430] DEBUG Observed 3 frame(s) via path ()
2023-04-02 17:06:53,737 aioax25.station.peer.VK4MSL[peer.py: 592] DEBUG RR notification received from peer
2023-04-02 17:06:53,737 aioax25.station.peer.VK4MSL[peer.py: 654] DEBUG 1 through to 0 are received
2023-04-02 17:06:53,738 asyncio[base_events.py:1752] ERROR Exception in callback AX25Station._on_receive(interface=<aioax25.inte...x7f26b28c17e0>, frame=<aioax25.fram...x7f26b28c2740>)()
handle: <Handle AX25Station._on_receive(interface=<aioax25.inte...x7f26b28c17e0>, frame=<aioax25.fram...x7f26b28c2740>)()>
Traceback (most recent call last):
File "/usr/lib/python3.10/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
File "/home/stuartl/projects/wicen/rfid/aioax25/aioax25/station.py", line 206, in _on_receive
peer._on_receive(frame)
File "/home/stuartl/projects/wicen/rfid/aioax25/aioax25/peer.py", line 506, in _on_receive
return self._on_receive_sframe(frame)
File "/home/stuartl/projects/wicen/rfid/aioax25/aioax25/peer.py", line 577, in _on_receive_sframe
self._on_receive_rr(frame)
File "/home/stuartl/projects/wicen/rfid/aioax25/aioax25/peer.py", line 595, in _on_receive_rr
self._ack_outstanding((frame.nr - 1) % self._modulo)
File "/home/stuartl/projects/wicen/rfid/aioax25/aioax25/peer.py", line 656, in _ack_outstanding
self._pending_iframes.pop(self._send_state)
KeyError: 1
2023-04-02 17:07:17,679 aioax25.kiss[kiss.py: 223] DEBUG RECV RAW 'c000ac96689aa698e8ac96689aa6986120f048656c6c6f2041582e323520576f726c640dc0'
2023-04-02 17:07:17,679 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:07:17,679 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 1
2023-04-02 17:07:17,679 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME , REMAINING c000ac96689aa698e8ac96689aa6986120f048656c6c6f2041582e323520576f726c640dc0
2023-04-02 17:07:17,680 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:07:17,680 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 36
2023-04-02 17:07:17,680 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME 00ac96689aa698e8ac96689aa6986120f048656c6c6f2041582e323520576f726c640d, REMAINING c0
2023-04-02 17:07:17,680 aioax25.kiss[kiss.py: 315] DEBUG RECV FRAME dispatch KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986120f048656c6c6f2041582e323520576f726c640d}
2023-04-02 17:07:17,680 aioax25.kiss.port0[kiss.py: 661] DEBUG Received frame KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986120f048656c6c6f2041582e323520576f726c640d}
2023-04-02 17:07:17,680 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330573.4991429472
2023-04-02 17:07:17,681 aioax25.interface[router.py: 100] DEBUG Handling incoming frame VK4MSL>VK4MSL-4*
2023-04-02 17:07:17,681 aioax25.interface[router.py: 142] DEBUG Dispatching frame to 1 receivers
2023-04-02 17:07:17,681 aioax25.station[station.py: 195] DEBUG Checking command frame sub-class: VK4MSL>VK4MSL-4*
2023-04-02 17:07:17,681 aioax25.station[station.py: 205] DEBUG Passing frame to peer VK4MSL: VK4MSL>VK4MSL-4*
2023-04-02 17:07:17,681 aioax25.station.peer.VK4MSL[peer.py: 430] DEBUG Observed 4 frame(s) via path ()
2023-04-02 17:07:17,681 connection.VK4MSL[teststn.py: 27] INFO Received: b'Hello AX.25 World\r'
2023-04-02 17:07:17,681 aioax25.station.peer.VK4MSL[peer.py:1385] DEBUG Creating new I-Frame 1
2023-04-02 17:07:17,682 aioax25.station.peer.VK4MSL[peer.py:1388] DEBUG Sending new I-Frame 1
2023-04-02 17:07:17,682 aioax25.interface[interface.py: 63] DEBUG Adding to queue: VK4MSL-4>VK4MSL: N(R)=0 P/F=False N(S)=1 PID=0xf0 Payload=b"You sent: b'Hello AX.25 World\\r'\r\n"
2023-04-02 17:07:17,682 aioax25.interface[interface.py: 113] DEBUG Scheduling next transmission in 0.01814797817496583
2023-04-02 17:07:17,701 aioax25.interface[interface.py: 145] DEBUG Transmitting VK4MSL-4>VK4MSL: N(R)=0 P/F=False N(S)=1 PID=0xf0 Payload=b"You sent: b'Hello AX.25 World\\r'\r\n"
2023-04-02 17:07:17,702 aioax25.kiss.port0[kiss.py: 654] DEBUG XMIT AX.25 VK4MSL-4>VK4MSL: N(R)=0 P/F=False N(S)=1 PID=0xf0 Payload=b"You sent: b'Hello AX.25 World\\r'\r\n"
2023-04-02 17:07:17,702 aioax25.kiss[kiss.py: 238] DEBUG XMIT FRAME '00ac96689aa69860ac96689aa698e902f0596f752073656e743a20622748656c6c6f2041582e323520576f726c645c72270d0a'
2023-04-02 17:07:17,702 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330573.5197353506
2023-04-02 17:07:17,702 aioax25.kiss[kiss.py: 331] DEBUG XMIT RAW 'c000ac96689aa69860ac96689aa698e902f0596f752073656e743a20622748656c6c6f2041582e323520576f726c645c72270d0ac0'
2023-04-02 17:07:20,743 aioax25.kiss[kiss.py: 223] DEBUG RECV RAW 'c000ac96689aa69868ac96689aa698e141c0'
2023-04-02 17:07:20,743 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:07:20,743 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 1
2023-04-02 17:07:20,744 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME , REMAINING c000ac96689aa69868ac96689aa698e141c0
2023-04-02 17:07:20,744 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:07:20,744 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 17
2023-04-02 17:07:20,744 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME 00ac96689aa69868ac96689aa698e141, REMAINING c0
2023-04-02 17:07:20,745 aioax25.kiss[kiss.py: 315] DEBUG RECV FRAME dispatch KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa69868ac96689aa698e141}
2023-04-02 17:07:20,745 aioax25.kiss.port0[kiss.py: 661] DEBUG Received frame KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa69868ac96689aa698e141}
2023-04-02 17:07:20,745 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330576.56225838483
2023-04-02 17:07:20,746 aioax25.interface[router.py: 100] DEBUG Handling incoming frame VK4MSL*>VK4MSL-4
2023-04-02 17:07:20,746 aioax25.interface[router.py: 142] DEBUG Dispatching frame to 1 receivers
2023-04-02 17:07:20,746 aioax25.station[station.py: 205] DEBUG Passing frame to peer VK4MSL: VK4MSL*>VK4MSL-4
2023-04-02 17:07:20,747 aioax25.station.peer.VK4MSL[peer.py: 430] DEBUG Observed 5 frame(s) via path ()
2023-04-02 17:07:20,747 aioax25.station.peer.VK4MSL[peer.py: 592] DEBUG RR notification received from peer
2023-04-02 17:07:20,747 aioax25.station.peer.VK4MSL[peer.py: 654] DEBUG 2 through to 1 are received
2023-04-02 17:07:20,748 asyncio[base_events.py:1752] ERROR Exception in callback AX25Station._on_receive(interface=<aioax25.inte...x7f26b28c17e0>, frame=<aioax25.fram...x7f26b28c2a10>)()
handle: <Handle AX25Station._on_receive(interface=<aioax25.inte...x7f26b28c17e0>, frame=<aioax25.fram...x7f26b28c2a10>)()>
Traceback (most recent call last):
File "/usr/lib/python3.10/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
File "/home/stuartl/projects/wicen/rfid/aioax25/aioax25/station.py", line 206, in _on_receive
peer._on_receive(frame)
File "/home/stuartl/projects/wicen/rfid/aioax25/aioax25/peer.py", line 506, in _on_receive
return self._on_receive_sframe(frame)
File "/home/stuartl/projects/wicen/rfid/aioax25/aioax25/peer.py", line 577, in _on_receive_sframe
self._on_receive_rr(frame)
File "/home/stuartl/projects/wicen/rfid/aioax25/aioax25/peer.py", line 595, in _on_receive_rr
self._ack_outstanding((frame.nr - 1) % self._modulo)
File "/home/stuartl/projects/wicen/rfid/aioax25/aioax25/peer.py", line 656, in _ack_outstanding
self._pending_iframes.pop(self._send_state)
KeyError: 2
2023-04-02 17:07:26,758 aioax25.kiss[kiss.py: 223] DEBUG RECV RAW 'c000ac96689aa698e8ac96689aa6986151c0'
2023-04-02 17:07:26,759 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:07:26,759 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 1
2023-04-02 17:07:26,759 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME , REMAINING c000ac96689aa698e8ac96689aa6986151c0
2023-04-02 17:07:26,759 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:07:26,759 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 17
2023-04-02 17:07:26,759 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME 00ac96689aa698e8ac96689aa6986151, REMAINING c0
2023-04-02 17:07:26,760 aioax25.kiss[kiss.py: 315] DEBUG RECV FRAME dispatch KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986151}
2023-04-02 17:07:26,760 aioax25.kiss.port0[kiss.py: 661] DEBUG Received frame KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986151}
2023-04-02 17:07:26,760 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330582.57630282396
2023-04-02 17:07:26,761 aioax25.interface[router.py: 100] DEBUG Handling incoming frame VK4MSL>VK4MSL-4*
2023-04-02 17:07:26,761 aioax25.interface[router.py: 142] DEBUG Dispatching frame to 1 receivers
2023-04-02 17:07:26,762 aioax25.station[station.py: 195] DEBUG Checking command frame sub-class: VK4MSL>VK4MSL-4*
2023-04-02 17:07:26,762 aioax25.station[station.py: 205] DEBUG Passing frame to peer VK4MSL: VK4MSL>VK4MSL-4*
2023-04-02 17:07:26,762 aioax25.station.peer.VK4MSL[peer.py: 430] DEBUG Observed 6 frame(s) via path ()
2023-04-02 17:07:26,763 aioax25.station.peer.VK4MSL[peer.py: 588] DEBUG RR status requested from peer
2023-04-02 17:07:26,763 aioax25.station.peer.VK4MSL[peer.py: 647] DEBUG RR poll request from peer: we're ready
2023-04-02 17:07:26,763 aioax25.interface[interface.py: 63] DEBUG Adding to queue: VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:07:26,764 aioax25.interface[interface.py: 113] DEBUG Scheduling next transmission in 0.013526807946618646
2023-04-02 17:07:26,778 aioax25.interface[interface.py: 145] DEBUG Transmitting VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:07:26,779 aioax25.kiss.port0[kiss.py: 654] DEBUG XMIT AX.25 VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:07:26,779 aioax25.kiss[kiss.py: 238] DEBUG XMIT FRAME '00ac96689aa69860ac96689aa698e921'
2023-04-02 17:07:26,779 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330582.5900351213
2023-04-02 17:07:26,780 aioax25.kiss[kiss.py: 331] DEBUG XMIT RAW 'c000ac96689aa69860ac96689aa698e921c0'
2023-04-02 17:07:45,191 aioax25.kiss[kiss.py: 223] DEBUG RECV RAW 'c000ac96689aa698e8ac96689aa6986151c0'
2023-04-02 17:07:45,191 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:07:45,191 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 1
2023-04-02 17:07:45,191 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME , REMAINING c000ac96689aa698e8ac96689aa6986151c0
2023-04-02 17:07:45,192 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:07:45,192 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 17
2023-04-02 17:07:45,192 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME 00ac96689aa698e8ac96689aa6986151, REMAINING c0
2023-04-02 17:07:45,192 aioax25.kiss[kiss.py: 315] DEBUG RECV FRAME dispatch KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986151}
2023-04-02 17:07:45,193 aioax25.kiss.port0[kiss.py: 661] DEBUG Received frame KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986151}
2023-04-02 17:07:45,193 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330601.00604573794
2023-04-02 17:07:45,193 aioax25.interface[router.py: 100] DEBUG Handling incoming frame VK4MSL>VK4MSL-4*
2023-04-02 17:07:45,193 aioax25.interface[router.py: 142] DEBUG Dispatching frame to 1 receivers
2023-04-02 17:07:45,193 aioax25.station[station.py: 195] DEBUG Checking command frame sub-class: VK4MSL>VK4MSL-4*
2023-04-02 17:07:45,194 aioax25.station[station.py: 205] DEBUG Passing frame to peer VK4MSL: VK4MSL>VK4MSL-4*
2023-04-02 17:07:45,194 aioax25.station.peer.VK4MSL[peer.py: 430] DEBUG Observed 7 frame(s) via path ()
2023-04-02 17:07:45,194 aioax25.station.peer.VK4MSL[peer.py: 588] DEBUG RR status requested from peer
2023-04-02 17:07:45,194 aioax25.station.peer.VK4MSL[peer.py: 647] DEBUG RR poll request from peer: we're ready
2023-04-02 17:07:45,194 aioax25.interface[interface.py: 63] DEBUG Adding to queue: VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:07:45,194 aioax25.interface[interface.py: 113] DEBUG Scheduling next transmission in 0.012900829955469817
2023-04-02 17:07:45,208 aioax25.interface[interface.py: 145] DEBUG Transmitting VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:07:45,209 aioax25.kiss.port0[kiss.py: 654] DEBUG XMIT AX.25 VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:07:45,209 aioax25.kiss[kiss.py: 238] DEBUG XMIT FRAME '00ac96689aa69860ac96689aa698e921'
2023-04-02 17:07:45,209 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330601.0191794144
2023-04-02 17:07:45,210 aioax25.kiss[kiss.py: 331] DEBUG XMIT RAW 'c000ac96689aa69860ac96689aa698e921c0'
2023-04-02 17:08:12,327 aioax25.kiss[kiss.py: 223] DEBUG RECV RAW 'c000ac96689aa698e8ac96689aa6986151c0'
2023-04-02 17:08:12,327 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:08:12,327 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 1
2023-04-02 17:08:12,328 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME , REMAINING c000ac96689aa698e8ac96689aa6986151c0
2023-04-02 17:08:12,328 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:08:12,328 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 17
2023-04-02 17:08:12,328 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME 00ac96689aa698e8ac96689aa6986151, REMAINING c0
2023-04-02 17:08:12,329 aioax25.kiss[kiss.py: 315] DEBUG RECV FRAME dispatch KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986151}
2023-04-02 17:08:12,329 aioax25.kiss.port0[kiss.py: 661] DEBUG Received frame KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986151}
2023-04-02 17:08:12,329 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330628.1446953749
2023-04-02 17:08:12,330 aioax25.interface[router.py: 100] DEBUG Handling incoming frame VK4MSL>VK4MSL-4*
2023-04-02 17:08:12,330 aioax25.interface[router.py: 142] DEBUG Dispatching frame to 1 receivers
2023-04-02 17:08:12,330 aioax25.station[station.py: 195] DEBUG Checking command frame sub-class: VK4MSL>VK4MSL-4*
2023-04-02 17:08:12,331 aioax25.station[station.py: 205] DEBUG Passing frame to peer VK4MSL: VK4MSL>VK4MSL-4*
2023-04-02 17:08:12,331 aioax25.station.peer.VK4MSL[peer.py: 430] DEBUG Observed 8 frame(s) via path ()
2023-04-02 17:08:12,331 aioax25.station.peer.VK4MSL[peer.py: 588] DEBUG RR status requested from peer
2023-04-02 17:08:12,332 aioax25.station.peer.VK4MSL[peer.py: 647] DEBUG RR poll request from peer: we're ready
2023-04-02 17:08:12,332 aioax25.interface[interface.py: 63] DEBUG Adding to queue: VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:08:12,332 aioax25.interface[interface.py: 113] DEBUG Scheduling next transmission in 0.013330457906704396
2023-04-02 17:08:12,347 aioax25.interface[interface.py: 145] DEBUG Transmitting VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:08:12,347 aioax25.kiss.port0[kiss.py: 654] DEBUG XMIT AX.25 VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:08:12,348 aioax25.kiss[kiss.py: 238] DEBUG XMIT FRAME '00ac96689aa69860ac96689aa698e921'
2023-04-02 17:08:12,348 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330628.16035707266
2023-04-02 17:08:12,349 aioax25.kiss[kiss.py: 331] DEBUG XMIT RAW 'c000ac96689aa69860ac96689aa698e921c0'
2023-04-02 17:08:51,239 aioax25.kiss[kiss.py: 223] DEBUG RECV RAW 'c000ac96689aa698e8ac96689aa6986151c0'
2023-04-02 17:08:51,239 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:08:51,239 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 1
2023-04-02 17:08:51,240 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME , REMAINING c000ac96689aa698e8ac96689aa6986151c0
2023-04-02 17:08:51,240 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:08:51,240 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 17
2023-04-02 17:08:51,240 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME 00ac96689aa698e8ac96689aa6986151, REMAINING c0
2023-04-02 17:08:51,240 aioax25.kiss[kiss.py: 315] DEBUG RECV FRAME dispatch KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986151}
2023-04-02 17:08:51,241 aioax25.kiss.port0[kiss.py: 661] DEBUG Received frame KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986151}
2023-04-02 17:08:51,241 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330667.0519167723
2023-04-02 17:08:51,241 aioax25.interface[router.py: 100] DEBUG Handling incoming frame VK4MSL>VK4MSL-4*
2023-04-02 17:08:51,241 aioax25.interface[router.py: 142] DEBUG Dispatching frame to 1 receivers
2023-04-02 17:08:51,242 aioax25.station[station.py: 195] DEBUG Checking command frame sub-class: VK4MSL>VK4MSL-4*
2023-04-02 17:08:51,242 aioax25.station[station.py: 205] DEBUG Passing frame to peer VK4MSL: VK4MSL>VK4MSL-4*
2023-04-02 17:08:51,242 aioax25.station.peer.VK4MSL[peer.py: 430] DEBUG Observed 9 frame(s) via path ()
2023-04-02 17:08:51,243 aioax25.station.peer.VK4MSL[peer.py: 588] DEBUG RR status requested from peer
2023-04-02 17:08:51,243 aioax25.station.peer.VK4MSL[peer.py: 647] DEBUG RR poll request from peer: we're ready
2023-04-02 17:08:51,243 aioax25.interface[interface.py: 63] DEBUG Adding to queue: VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:08:51,243 aioax25.interface[interface.py: 113] DEBUG Scheduling next transmission in 0.009609530330635607
2023-04-02 17:08:51,254 aioax25.interface[interface.py: 145] DEBUG Transmitting VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:08:51,254 aioax25.kiss.port0[kiss.py: 654] DEBUG XMIT AX.25 VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:08:51,254 aioax25.kiss[kiss.py: 238] DEBUG XMIT FRAME '00ac96689aa69860ac96689aa698e921'
2023-04-02 17:08:51,254 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330667.0676130393
2023-04-02 17:08:51,254 aioax25.kiss[kiss.py: 331] DEBUG XMIT RAW 'c000ac96689aa69860ac96689aa698e921c0'
2023-04-02 17:09:36,295 aioax25.kiss[kiss.py: 223] DEBUG RECV RAW 'c000ac96689aa698e8ac96689aa6986151c0'
2023-04-02 17:09:36,295 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:09:36,295 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 1
2023-04-02 17:09:36,296 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME , REMAINING c000ac96689aa698e8ac96689aa6986151c0
2023-04-02 17:09:36,296 aioax25.kiss[kiss.py: 260] DEBUG RECV FRAME start at 0
2023-04-02 17:09:36,296 aioax25.kiss[kiss.py: 274] DEBUG RECV FRAME end at 17
2023-04-02 17:09:36,296 aioax25.kiss[kiss.py: 281] DEBUG RECEIVED FRAME 00ac96689aa698e8ac96689aa6986151, REMAINING c0
2023-04-02 17:09:36,296 aioax25.kiss[kiss.py: 315] DEBUG RECV FRAME dispatch KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986151}
2023-04-02 17:09:36,297 aioax25.kiss.port0[kiss.py: 661] DEBUG Received frame KISSCmdData{Port 0, Cmd 0x00, Payload ac96689aa698e8ac96689aa6986151}
2023-04-02 17:09:36,297 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330712.108522285
2023-04-02 17:09:36,297 aioax25.interface[router.py: 100] DEBUG Handling incoming frame VK4MSL>VK4MSL-4*
2023-04-02 17:09:36,297 aioax25.interface[router.py: 142] DEBUG Dispatching frame to 1 receivers
2023-04-02 17:09:36,298 aioax25.station[station.py: 195] DEBUG Checking command frame sub-class: VK4MSL>VK4MSL-4*
2023-04-02 17:09:36,298 aioax25.station[station.py: 205] DEBUG Passing frame to peer VK4MSL: VK4MSL>VK4MSL-4*
2023-04-02 17:09:36,298 aioax25.station.peer.VK4MSL[peer.py: 430] DEBUG Observed 10 frame(s) via path ()
2023-04-02 17:09:36,299 aioax25.station.peer.VK4MSL[peer.py: 588] DEBUG RR status requested from peer
2023-04-02 17:09:36,299 aioax25.station.peer.VK4MSL[peer.py: 647] DEBUG RR poll request from peer: we're ready
2023-04-02 17:09:36,299 aioax25.interface[interface.py: 63] DEBUG Adding to queue: VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:09:36,299 aioax25.interface[interface.py: 113] DEBUG Scheduling next transmission in 0.009934081987012178
2023-04-02 17:09:36,310 aioax25.interface[interface.py: 145] DEBUG Transmitting VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:09:36,311 aioax25.kiss.port0[kiss.py: 654] DEBUG XMIT AX.25 VK4MSL-4>VK4MSL: N(R)=1 P/F=False AX258BitReceiveReadyFrame
2023-04-02 17:09:36,311 aioax25.kiss[kiss.py: 238] DEBUG XMIT FRAME '00ac96689aa69860ac96689aa698e921'
2023-04-02 17:09:36,311 aioax25.interface[interface.py: 92] DEBUG Clear-to-send expiry at 330712.1260440837
2023-04-02 17:09:36,311 aioax25.kiss[kiss.py: 331] DEBUG XMIT RAW 'c000ac96689aa69860ac96689aa698e921c0'
Raw
teststn.py
#!/usr/bin/env python3
import logging
from asyncio import run, sleep
from aioax25.station import AX25Station
from aioax25.kiss import make_device
from aioax25.interface import AX25Interface
def _on_connection_rq(peer, **kwargs):
log = logging.getLogger("connection.%s" % peer.address)
log.info("Incoming connection from %s", peer.address)
def _on_state_change(state, **kwargs):
log.info("State is now %s", state)
if state is peer.AX25PeerState.CONNECTED:
peer.send(("Hello %s\r\n" % peer.address).encode())
def _on_rx(payload, **kwargs):
try:
payload = payload.decode()
except Exception as e:
log.exception("Could not decode %r", payload)
peer.send("Could not decode %r: %s", payload, e)
return
log.info("Received: %r", payload)
peer.send(("You sent: %r\r\n" % payload).encode())
if payload == "bye\r":
peer.send(("Disconnecting\r\n").encode())
peer.disconnect()
peer.connect_state_changed.connect(_on_state_change)
peer.received_information.connect(_on_rx)
peer.accept()
async def asyncmain():
logging.basicConfig(
level=logging.DEBUG,
format='%(asctime)s %(name)s[%(filename)s:%(lineno)4d] %(levelname)s %(message)s'
)
kissdev = make_device(
type="serial", device="/dev/ax0", baudrate=9600,
reset_on_close=False, kiss_commands=[]
)
interface = AX25Interface(kissdev[0])
station = AX25Station(
interface=interface,
callsign="VK4MSL", ssid=4
)
station.connection_request.connect(_on_connection_rq)
station.attach()
kissdev.open()
logging.getLogger("asyncmain").info("Waiting for connections")
try:
while True:
await sleep(10)
except KeyboardInterrupt:
pass
station.detach()
kissdev.close()
run(asyncmain())
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment