search

ham-radio-software / D-Rats

D-Rats program for D-Star Ham Radios
https://iz2lxi.jimdofree.com/
Other
41 stars 12 forks source link

Chat TX/RX - DRats 0.3.10 to 0.4.1.dev18-g4406b3d-dirty #262

Closed maurizioandreotti closed 8 months ago

maurizioandreotti commented 9 months ago

Today some 2hour TR/RX tests - reporting here some outcomes and console logs to support troubleshooting.

All the stations below were in same locations for both the tests scenarios with the configuration usually adopted for D-rats 0.3.x As all three stations were able to receive clear audio between them and all radios were showing callnames at RX time at all times the expectation was that each station was able to receive all chats when other stations were transmitting. (i.e. everybody able to hear anybody at anytime).

Setup:

Scenario A - setup and results

Scenario B - setup and results station FOW: 0.3.10 with ID5100 --can receive D-Rats chat from both BDZ and FOW station BDZ: 0.4.1dev18 with ID51 -- can receive D-Rats chat from both LXI and FOW station LXI: 0.4.1dev18 with IC2820 -- can not receive D-Rats chat from other (but can transmit) (reverting to 0.3.10 the chat was receivable)

Log from BDZ:

Administrator@FLYRAD1 MINGW64 ~/D-Rats
# ./d-rats.py
10/22/2023 16:08:06:INFO:D-Rats:main: re-config option found -- Reconfigure D-rats
10/22/2023 16:08:06:INFO:D-Rats:main: args.config = C:/Users/Administrator/AppData/Roaming/D-RATS-EV
10/22/2023 16:08:06:INFO:Mainapp:Enabled debug log for Win32 systems
10/22/2023 16:08:06:INFO:QST:FeedParser not available
10/22/2023 16:08:07:INFO:DratsConfig:File C:/Users/Administrator/AppData/Roaming/D-RATS-EV/d-rats.co
nfig
10/22/2023 16:08:07:INFO:MainApp:_refresh_lang: Loading locale `it'
10/22/2023 16:08:07:INFO:MainApp:_refresh_lang: Locale dir is: D:/msys64/home/Administrator/D-Rats/l
ocale
10/22/2023 16:08:07:ERROR:MainApp:_refresh_lang: Messages catalog file missing  for it.  Need to use
 'msgfmt tool to generate.
10/22/2023 16:08:07:INFO:MainApp:D-RATS v0.4.1.dev17-ga0b0c90 starting at Sun Oct 22 16:08:07 2023 o
n Platform Win32Platform:
  configuration:       C:/Users/Administrator/AppData/Roaming/D-RATS-EV
  system_data: D:/msys64/home/Administrator/D-Rats
  OS version: Windows 10 (10, 0, 19045, 2, '')
10/22/2023 16:08:07:INFO:MainApp:load position from config file
10/22/2023 16:08:07:INFO:MainApp:_static_gps: Configuring the Static position: 45.820300,9.379220
10/22/2023 16:08:07:INFO:MainApp:_static_gps: Mapserver not active: False, call: IU2BDZ
10/22/2023 16:08:07:INFO:StaticGPSSource:StaticGPSPosition: UNKNOWN reporting 45.8203,9.3792@420 ft
at 16:08:07
10/22/2023 16:08:07:INFO:D-Rats:main: reloading app

10/22/2023 16:08:07:INFO:MainApp:load the main window
10/22/2023 16:08:07:INFO:MainApp:load main window with self config
10/22/2023 16:08:09:INFO:DRatsPluginServer:Started serve_forever() thread
10/22/2023 16:08:09:INFO:MessageRouter:_route_via_station: Starting message router thread
10/22/2023 16:08:09:INFO:MainApp:connect main window
10/22/2023 16:08:09:INFO:MainApp:connect tabs
10/22/2023 16:08:09:INFO:MainApp:going online
10/22/2023 16:08:09:INFO:MessageRouter:_run_one: Station list was empty
10/22/2023 16:08:09:INFO:MainApp:create map window object-----
10/22/2023 16:08:09:INFO:MapWindow:init MapWindow
10/22/2023 16:08:09:INFO:MainApp:create map window object: connect object-----
10/22/2023 16:08:09:INFO:MainApp:query local gps device to see our current position
10/22/2023 16:08:09:INFO:APRSicons:get_icon: Unknown APRS symbol table: x
10/22/2023 16:08:09:INFO:MainApp:invoke config refresh
10/22/2023 16:08:09:INFO:MainApp:Refreshing config...
10/22/2023 16:08:09:INFO:gps:set_units: Set GPS units to Metric
10/22/2023 16:08:09:INFO:MainApp:refresh comms
10/22/2023 16:08:09:INFO:MainApp:_refresh_comms: Re-Starting ports_0
10/22/2023 16:08:09:INFO:MainApp:Starting Comms
10/22/2023 16:08:09:INFO:MainApp:_refresh_comms: Re-Starting ports_1
10/22/2023 16:08:09:INFO:MainApp:Starting Comms
10/22/2023 16:08:09:INFO:MainApp:start_comms: Starting port ports_1 (USBsu5)
10/22/2023 16:08:09:INFO:MainApp:check_comms_status: Ports expected to be already started:
10/22/2023 16:08:09:INFO:SWFSerial:Software XON/XOFF control initialized
10/22/2023 16:08:09:INFO:MainApp:check_comms_status: USBsu5
10/22/2023 16:08:09:INFO:MainApp:check_comms_status: Checking all Ports from config:
10/22/2023 16:08:09:INFO:MainApp:check_comms_status: portid ports_0
10/22/2023 16:08:09:INFO:MainApp:check_comms_status: Port RAT not started
10/22/2023 16:08:09:INFO:MainApp:check_comms_status: portid ports_1
10/22/2023 16:08:09:INFO:MainApp:check_comms_status: Port USBsu5 already started!
10/22/2023 16:08:09:INFO:MainApp:_refresh_gps : GPS: True on @4800
10/22/2023 16:08:09:INFO:GPSSource:Unable to open port `'
10/22/2023 16:08:09:INFO:GPSSource:start: Not starting broken GPSSource
10/22/2023 16:08:09:INFO:MainApp:_refresh_map: reconfigure Mapwindow with new map
10/22/2023 16:08:09:INFO:MainApp:_refresh_map: reconfigured mapurl to: http://tile.thunderforest.com
/cycle/
10/22/2023 16:08:09:INFO:MainApp:_refresh_map: reconfigured mapkey to: ?apikey=5a1a4a79354244a38707d
83969fd88a1
10/22/2023 16:08:21:INFO:Transporter:send_frames: [SERIAL COM5@9600] Waiting 0.6 sec before transmit
ting
10/22/2023 16:08:22:INFO:Transporter:send_frames: [SERIAL COM5@9600] Sending warm-up: DDT2-: 0:0:254
 !->! (...[8])
10/22/2023 16:08:22:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:08:29:INFO:SessionManager:incoming: Received block 0:0 for session `chat'
10/22/2023 16:08:32:INFO:Transporter:send_frames: [SERIAL COM5@9600] Waiting 1.5 sec before transmit
ting
10/22/2023 16:08:34:INFO:Transporter:send_frames: [SERIAL COM5@9600] Sending warm-up: DDT2-: 0:0:254
 !->! (...[8])
10/22/2023 16:08:34:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:08:40:INFO:SessionManager:incoming: Received block 0:0 for session `chat'
10/22/2023 16:09:20:INFO:SessionManager:incoming:Received frame for station `!'
10/22/2023 16:09:20:INFO:SessionManager:incoming: Received block 0:0 for session `chat'
10/22/2023 16:09:32:INFO:Transporter:send_frames: [SERIAL COM5@9600] Waiting 1.9 sec before transmit
ting
10/22/2023 16:09:34:INFO:Transporter:send_frames: [SERIAL COM5@9600] Sending warm-up: DDT2-: 0:0:254
 !->! (...[8])
10/22/2023 16:09:34:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:08:INFO:SessionManager:incoming: Received block 0:0 for session `chat'
10/22/2023 16:10:45:INFO:Transporter:send_frames: [SERIAL COM5@9600] Waiting 1.9 sec before transmit
ting
10/22/2023 16:10:46:INFO:Transporter:send_frames: [SERIAL COM5@9600] Sending warm-up: DDT2-: 0:0:254
 !->! (...[8])
10/22/2023 16:10:46:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:46:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:46:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:46:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:46:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:47:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:47:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:47:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:47:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:47:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:47:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:47:INFO:SWFSerial:is_xon: Assuming IXANY behavior
10/22/2023 16:10:47:INFO:SWFSerial:is_xon: Assuming IXANY behavior
**10/22/2023 16:10:47:INFO:DDT2EncodedFrame:unpack: Block has no header/trailer
Traceback (most recent call last):
  File "D:/msys64/home/Administrator/D-Rats/d_rats/ddt2.py", line 338, in unpack
    h_index = val.index(ENCODED_HEADER) + len(ENCODED_TRAILER)
              ^^^^^^^^^^^^^^^^^^^^^^^^^
ValueError: subsection not found**
5b9080 (d_rats+sessions+rpc+RPCActionSet at 0x00000213a8f24ea0)>
10/22/2023 16:14:03:INFO:RPCActionSet:rpc_pos_report: port is : USBsu5
10/22/2023 16:14:03:INFO:RPCActionSet:rpc_pos_report: fix is: IU2BDZ reporting 0.0000,0.0000@0 m at
16:08:09
10/22/2023 16:14:03:INFO:RPCActionSet:rpc_pos_report: fix in NMEA GGA is: $GPGGA,161403,0.000,S,0.00
0,W,1,3,0,0,M,0,M,,*61
IU2BDZ  ,BD  *58

10/22/2023 16:14:03:INFO:RPCActionSet:rpc_pos_report: fix in APRS is: {'rc': 'True', 'msg': '$$CRCF4
90,IU2BDZ>APRATS,DSTAR*:/141403h0000.00S/00000.00W>\r\n'}
10/22/2023 16:14:03:INFO:SessionManager:incoming: Received block 1:0 for session `rpc'
10/22/2023 16:14:03:INFO:Transporter:send_frames: [SERIAL COM5@9600] Waiting 2.0 sec before transmit
ting

LOG from LXI:

10/22/2023 16:35:12:INFO:Utils.log_exception:-- Exception: --
Traceback (most recent call last):
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 717, in read
    data = self._serial.read(size)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 462, in read
    return serial.Serial.read(self, size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/mingw64/lib/python3.11/site-packages/serial/serialwin32.py", line 275, in read
    raise SerialException("ClearCommError failed ({!r})".format(ctypes.WinError()))
serial.serialutil.SerialException: ClearCommError failed (OSError(22, 'The I/O operation has been ab
orted because of either a thread exit or an application request.', None, 995))
10/22/2023 16:35:12:INFO:Utils.log_exception:----------------
10/22/2023 16:35:12:INFO:Transporter:__recv: [SERIAL COM6@9600] Data path IO error: Failed to read f
rom serial port [SERIAL COM6@9600] ClearCommError failed (OSError(22, 'The I/O operation has been ab
orted because of either a thread exit or an application request.', None, 995))
10/22/2023 16:35:12:INFO:Transporter:__recv: [SERIAL COM6@9600] Attempting reconnect...
10/22/2023 16:35:12:INFO:Utils.log_exception:-- Exception: --
Traceback (most recent call last):
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 717, in read
    data = self._serial.read(size)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 462, in read
    return serial.Serial.read(self, size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/mingw64/lib/python3.11/site-packages/serial/serialwin32.py", line 275, in read
    raise SerialException("ClearCommError failed ({!r})".format(ctypes.WinError()))
serial.serialutil.SerialException: ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:12:INFO:Utils.log_exception:----------------
10/22/2023 16:35:12:INFO:Transporter:__recv: [SERIAL COM6@9600] Data path IO error: Failed to read f
rom serial port [SERIAL COM6@9600] ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:13:INFO:Transporter:__recv: [SERIAL COM6@9600] Attempting reconnect...
10/22/2023 16:35:13:INFO:Utils.log_exception:-- Exception: --
Traceback (most recent call last):
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 717, in read
    data = self._serial.read(size)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 462, in read
    return serial.Serial.read(self, size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/mingw64/lib/python3.11/site-packages/serial/serialwin32.py", line 275, in read
    raise SerialException("ClearCommError failed ({!r})".format(ctypes.WinError()))
serial.serialutil.SerialException: ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:13:INFO:Utils.log_exception:----------------
10/22/2023 16:35:13:INFO:Transporter:__recv: [SERIAL COM6@9600] Data path IO error: Failed to read f
rom serial port [SERIAL COM6@9600] ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:15:INFO:Transporter:__recv: [SERIAL COM6@9600] Attempting reconnect...
10/22/2023 16:35:15:INFO:Utils.log_exception:-- Exception: --
Traceback (most recent call last):
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 717, in read
    data = self._serial.read(size)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 462, in read
    return serial.Serial.read(self, size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/mingw64/lib/python3.11/site-packages/serial/serialwin32.py", line 275, in read
    raise SerialException("ClearCommError failed ({!r})".format(ctypes.WinError()))
serial.serialutil.SerialException: ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:15:INFO:Utils.log_exception:----------------
10/22/2023 16:35:15:INFO:Transporter:__recv: [SERIAL COM6@9600] Data path IO error: Failed to read f
rom serial port [SERIAL COM6@9600] ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:18:INFO:Transporter:__recv: [SERIAL COM6@9600] Attempting reconnect...
10/22/2023 16:35:18:INFO:Utils.log_exception:-- Exception: --
Traceback (most recent call last):
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 717, in read
    data = self._serial.read(size)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 462, in read
    return serial.Serial.read(self, size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/mingw64/lib/python3.11/site-packages/serial/serialwin32.py", line 275, in read
    raise SerialException("ClearCommError failed ({!r})".format(ctypes.WinError()))
serial.serialutil.SerialException: ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:18:INFO:Utils.log_exception:----------------
10/22/2023 16:35:18:INFO:Transporter:__recv: [SERIAL COM6@9600] Data path IO error: Failed to read f
rom serial port [SERIAL COM6@9600] ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:22:INFO:Transporter:__recv: [SERIAL COM6@9600] Attempting reconnect...
10/22/2023 16:35:22:INFO:Utils.log_exception:-- Exception: --
Traceback (most recent call last):
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 717, in read
    data = self._serial.read(size)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 462, in read
    return serial.Serial.read(self, size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/mingw64/lib/python3.11/site-packages/serial/serialwin32.py", line 275, in read
    raise SerialException("ClearCommError failed ({!r})".format(ctypes.WinError()))
serial.serialutil.SerialException: ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:22:INFO:Utils.log_exception:----------------
10/22/2023 16:35:22:INFO:Transporter:__recv: [SERIAL COM6@9600] Data path IO error: Failed to read f
rom serial port [SERIAL COM6@9600] ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:27:INFO:Transporter:__recv: [SERIAL COM6@9600] Attempting reconnect...
10/22/2023 16:35:27:INFO:Utils.log_exception:-- Exception: --
Traceback (most recent call last):
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 717, in read
    data = self._serial.read(size)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/home/mauri/D-Rats-Master/d_rats/comm.py", line 462, in read
    return serial.Serial.read(self, size)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:/msys64/mingw64/lib/python3.11/site-packages/serial/serialwin32.py", line 275, in read
    raise SerialException("ClearCommError failed ({!r})".format(ctypes.WinError()))
serial.serialutil.SerialException: ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:27:INFO:Utils.log_exception:----------------
10/22/2023 16:35:27:INFO:Transporter:__recv: [SERIAL COM6@9600] Data path IO error: Failed to read f
rom serial port [SERIAL COM6@9600] ClearCommError failed (PermissionError(13, 'The device does not r
ecognize the command.', None, 22))
10/22/2023 16:35:31:INFO:MainWindow:_delete handler invoked <class 'gi.overrides.Gdk.Event'>
10/22/2023 16:35:31:INFO:MainApp:Saving config...
wb8tyw commented 9 months ago

This looks like another case where the driver XON/XOFF handling may not be working 100%.

The 0.3 version XON/XOFF is guaranteed to drop characters There may be something we do not know about some Radios that does not work with the driver XON/XOFF handling.

Ugolupo commented 9 months ago

iz2fow version corrections: my d-rats 0.3.9 Python 2.7.9 GTK 2.24.10 PyGTK 2.24.0 LibXML using 0.4 KB

wb8tyw commented 9 months ago

Just noticed from this bug report, that D-Rats was operating in Linux XANY mode, which requires that the device sending XOFF to send additional XOFFs codes if needed.

If the radio is not sending the additional XOFF codes, then this can result in data loss on transmission.

The PR-268 reverts to the previous behavior, except that incoming characters that show up instead of XON/XOFF are no longer discarded.