search

ham-radio-software / D-Rats

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

Serial port XON/XOFF handling totally broken #253

Closed maurizioandreotti closed 11 months ago

maurizioandreotti commented 1 year ago

InThe list of files which should appear when one is connected into the files

the following is a log of what apperared on a file transfer to my station with lates Drats 4 from a station with 0.3.10 the guy was able to push a file to my pc, but was not getting the file list from mine

I wasnt able to get connected to his pc and also to get his list of files

radio connection was on VHF at less than 1km distance, so no issue on TX/RX side

10/07/2023 14:50:29:INFO:SessionManager:incoming: Received block 0:0 for session chat' 10/07/2023 14:50:36:INFO:SessionManager:incoming:Received frame for station!' 10/07/2023 14:50:41:INFO:SessionManager:incoming: Received block 0:0 for session chat' 10/07/2023 14:50:58:INFO:SessionManager:incoming: Received block 0:0 for sessionchat' 10/07/2023 14:51:04:INFO:StationsList:_menu_handler: executing position request to: IZ2QDO 10/07/2023 14:51:04:INFO:RPCSession:Sending job Position Request' to IZ2QDO 10/07/2023 14:51:04:INFO:RPCSession:Job sent 10/07/2023 14:51:04:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 0.6 sec before transmitting 10/07/2023 14:51:05:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA10' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2Q' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>A' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>AP' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTA' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/1' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/12' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/0' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/00926' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/00926.' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/00926.31E>' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/00926.31E>B' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/00926.31E>BN C' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/00926.31E>BN CI' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/00926.31E>BN CIAO*2' 10/07/2023 14:51:09:INFO:Transporter:_match_gps: [SERIAL COM4@9600] Didn't match: b'\x11$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/00926.31E>BN CIAO*24' 10/07/2023 14:51:09:INFO:Transporter:_parse_gps: [SERIAL COM4@9600] Found GPS string: bytearray(b'$$CRCA103,IZ2QDO>APRATS,DSTAR*:/125107h4547.62N/00926.31E>BN CIAO*24\r') 10/07/2023 14:51:09:INFO:SessionManager:incoming: Received block 0:0 for sessionchat' 10/07/2023 14:51:09:INFO:MainApp:__incoming_gps_fix: Export to external mapserver not active: False 10/07/2023 14:51:09:INFO:StaticGPSSource:StaticGPSPosition: IZ2QDO relazione 45.7937,9.4385@0 ft at 14:51:09 10/07/2023 14:51:10:INFO:SessionManager:incoming: Received block 0:0 for session chat' 10/07/2023 14:51:16:INFO:SessionManager:incoming: Received block 0:0 for sessionchat' 10/07/2023 14:51:20:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 2.0 sec before transmitting 10/07/2023 14:51:35:INFO:RPCSession:worker: Cancelling job 1 due to timeout 10/07/2023 14:51:35:INFO:StationsList:_menu_handler: result returned: {} 10/07/2023 14:51:35:INFO:StationsList:_menu_handler: event returned: <d_rats.ui.main_events.Event object at 0x00000196936a67a0> 10/07/2023 14:51:36:INFO:ControlSession:ctl_new: New session 4 from remote 10/07/2023 14:51:36:INFO:ControlSession:ctl_new: sending ACK for session request for 4 10/07/2023 14:51:36:INFO:ControlSession:ctl_new: Got type: <class 'd_rats.sessions.file.FileTransferSession'> 10/07/2023 14:51:36:INFO:StatefulSession:queue_next: New limit is 4 (8/4), queueing 4 10/07/2023 14:51:36:INFO:FileTransferSession:XFER STATUS: 10/07/2023 14:51:36:INFO:FileTransferSession:worker: Session loop (None:switch.c) 10/07/2023 14:51:36:INFO:SessionManager:incoming: Received block 0:8 for session control' 10/07/2023 14:51:36:INFO:SessionCoordinator:New session (in) of type: <class 'd_rats.sessions.file.FileTransferSession'> 10/07/2023 14:51:36:INFO:FileTransferSession:worker: Deep sleep 10/07/2023 14:51:36:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 0.7 sec before transmitting 10/07/2023 14:51:36:INFO:MainApp:Session Started In: [SESSION 4]: FileTransfer 10/07/2023 14:51:36:INFO:FileTransferSession:worker: Awoke from deep sleep to some data 10/07/2023 14:51:36:INFO:FileTransferSession:queue_next: New limit is 4 (8/4), queueing 4 10/07/2023 14:51:36:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:36:INFO:MainApp:Session Started In: [SESSION 4]: Trasferimento file di switch.c avviato con IZ2QDO 10/07/2023 14:51:36:INFO:FileTransferSession:worker: Deep sleep 10/07/2023 14:51:36:INFO:MainApp:Session Started In: [SESSION 4]: In attesa avvio trasferimento [00%] 10/07/2023 14:51:41:INFO:SessionManager:incoming: Received block 0:4 for sessionswitch.c' 10/07/2023 14:51:41:INFO:FileTransferSession:worker: Awoke from deep sleep to some data 10/07/2023 14:51:41:INFO:FileTransferSession:queue_next: New limit is 4 (8/4), queueing 4 10/07/2023 14:51:41:INFO:FileTransferSession:recv_blocks: Got block 0 10/07/2023 14:51:41:INFO:FileTransferSession:recv_blocks: Waiting OOO blocks: [0] 10/07/2023 14:51:41:INFO:FileTransferSession:recv_blocks: Queuing now in-order block 0: DDT2+: 0:4:4 IZ2QDO->IZ2LXI-W (b'\x8a\x00\x00\x00switch.c'...[12]) 10/07/2023 14:51:41:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:41:INFO:FileTransferSession:worker: Deep sleep 10/07/2023 14:51:41:INFO:MainApp:Session Started In: [SESSION 4]: In attesa avvio trasferimento [00%] 10/07/2023 14:51:41:INFO:FileTransferSession:queue_next: New limit is 4 (8/4), queueing 4 10/07/2023 14:51:41:INFO:MainApp:Session Started In: [SESSION 4]: File in ricezione switch.c della dimensione 138 [00%] 10/07/2023 14:51:41:INFO:FileTransferSession:queue_next : Queuing 0 for send (4) 10/07/2023 14:51:41:INFO:MainApp:Session Started In: [SESSION 4]: File in ricezione switch.c della dimensione 138 [00%] 10/07/2023 14:51:41:INFO:FileTransferSession:write: Waiting for block 0 ACK to be received 10/07/2023 14:51:41:INFO:FileTransferSession:worker: Awoke from deep sleep to some data 10/07/2023 14:51:41:INFO:MainApp:Session Started In: [SESSION 4]: File in ricezione switch.c della dimensione 138 [00%] 10/07/2023 14:51:41:INFO:FileTransferSession:queue_next: New limit is 4 (8/4), queueing 3 10/07/2023 14:51:41:INFO:MainApp:Session Started In: [SESSION 4]: File in ricezione switch.c della dimensione 138 [00%] 10/07/2023 14:51:41:INFO:FileTransferSession:send_blocks: Sending 0 10/07/2023 14:51:41:INFO:FileTransferSession:send_reqack: Requesting ACK of blocks [0] 10/07/2023 14:51:41:INFO:FileTransferSession:send_blocks: Waiting for block to be sent 10/07/2023 14:51:41:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 1.3 sec before transmitting 10/07/2023 14:51:42:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:42:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:42:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:42:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:43:INFO:FileTransferSession:write: Block 0 is sent, waiting for ack 10/07/2023 14:51:43:INFO:FileTransferSession:update_xmt: Average transmit rate: 90 bps 10/07/2023 14:51:43:INFO:FileTransferSession:write: 0 No ACK received (probably canceled) 10/07/2023 14:51:43:INFO:FileTransferSession:send_blocks: Block sent after: 1.533267 10/07/2023 14:51:43:INFO:MainApp:Session Started In: [SESSION 4]: File in ricezione switch.c della dimensione 138 [00%] 0.00 B/s (Totale 2 B) 10/07/2023 14:51:43:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:43:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:43:INFO:MainApp:Session Started In: [SESSION 4]: In attesa primo blocco [00%] 0.00 B/s (Totale 2 B) 10/07/2023 14:51:43:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:44:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:44:INFO:FileTransferSession:is_timeout : ## Remaining: 9.3 sec 10/07/2023 14:51:44:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:44:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:45:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:45:INFO:FileTransferSession:is_timeout : ## Remaining: 8.2 sec 10/07/2023 14:51:45:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:45:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:46:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:46:INFO:FileTransferSession:is_timeout : ## Remaining: 7.1 sec 10/07/2023 14:51:46:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:46:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:47:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:47:INFO:FileTransferSession:is_timeout : ## Remaining: 6.1 sec 10/07/2023 14:51:47:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:47:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:47:INFO:DDT2EncodedFrame:unpack: Checksum failed: 25507 != 45861 10/07/2023 14:51:47:INFO:SessionManager:incoming: Received block 0:0 for session chat' 10/07/2023 14:51:48:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:48:INFO:FileTransferSession:is_timeout : ## Remaining: 5.0 sec 10/07/2023 14:51:48:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:48:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:49:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:49:INFO:FileTransferSession:is_timeout : ## Remaining: 3.9 sec 10/07/2023 14:51:49:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:49:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:50:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 0.7 sec before transmitting 10/07/2023 14:51:50:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:50:INFO:FileTransferSession:is_timeout : ## Remaining: 2.8 sec 10/07/2023 14:51:50:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:50:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:51:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:51:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:51:INFO:FileTransferSession:is_timeout : ## Remaining: 1.7 sec 10/07/2023 14:51:51:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:51:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:52:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:52:INFO:FileTransferSession:is_timeout : ## Remaining: 0.7 sec 10/07/2023 14:51:52:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:52:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:53:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:53:INFO:FileTransferSession:is_timeout : ## Remaining: -0.3 sec 10/07/2023 14:51:53:INFO:FileTransferSession:queue_next: New limit is 4 (8/4), queueing 3 10/07/2023 14:51:53:INFO:FileTransferSession:send_blocks: Didn't get last ack, asking again 10/07/2023 14:51:53:INFO:FileTransferSession:send_reqack: Requesting ACK of blocks [0] 10/07/2023 14:51:53:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:53:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:54:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 0.8 sec before transmitting 10/07/2023 14:51:54:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:54:INFO:FileTransferSession:is_timeout : ## Remaining: -1.4 sec 10/07/2023 14:51:54:INFO:FileTransferSession:is_timeout: ## Waiting for ACK, timeout in 6 10/07/2023 14:51:54:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:54:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:55:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:55:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:55:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:55:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:56:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:56:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:56:INFO:FileTransferSession:is_timeout : ## Remaining: -2.6 sec 10/07/2023 14:51:56:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:56:INFO:FileTransferSession:is_timeout: ## Waiting for ACK, timeout in 5 10/07/2023 14:51:56:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:56:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:56:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:51:56:INFO:DDT2EncodedFrame:unpack: Checksum failed: 25507 != 12938 10/07/2023 14:51:56:INFO:SessionManager:incoming: Received block 0:0 for sessionchat' 10/07/2023 14:51:57:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:57:INFO:FileTransferSession:is_timeout : ## Remaining: -3.9 sec 10/07/2023 14:51:57:INFO:FileTransferSession:is_timeout: ## Waiting for ACK, timeout in 4 10/07/2023 14:51:57:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:57:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:58:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:58:INFO:FileTransferSession:is_timeout : ## Remaining: -4.9 sec 10/07/2023 14:51:58:INFO:FileTransferSession:is_timeout: ## Waiting for ACK, timeout in 3 10/07/2023 14:51:58:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:58:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:59:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:59:INFO:FileTransferSession:is_timeout : ## Remaining: -6.0 sec 10/07/2023 14:51:59:INFO:FileTransferSession:is_timeout: ## Waiting for ACK, timeout in 2 10/07/2023 14:51:59:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:51:59:INFO:FileTransferSession:worker: Outstanding data, short sleep 10/07/2023 14:51:59:INFO:SessionManager:incoming: Received block 0:1 for session switch.c' 10/07/2023 14:51:59:INFO:FileTransferSession:is_timeout: ## Timeout for 35 bytes @ 80 bps: 12.0 sec 10/07/2023 14:51:59:INFO:FileTransferSession:is_timeout : ## Remaining: -6.5 sec 10/07/2023 14:52:00:INFO:FileTransferSession:is_timeout: ## Waiting for ACK, timeout in 1 10/07/2023 14:52:00:INFO:FileTransferSession:recv_blocks: Acked blocks: [0] (/1) 10/07/2023 14:52:00:INFO:MainApp:Session Started In: [SESSION 4]: In attesa primo blocco [00%] 0.00 B/s (Totale 2 B) 10/07/2023 14:52:00:INFO:FileTransferSession:recv_blocks: This was not a full ACK 10/07/2023 14:52:00:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:52:00:INFO:FileTransferSession:worker: Deep sleep 10/07/2023 14:52:00:INFO:SessionManager:incoming: Received block 0:5 for sessionswitch.c' 10/07/2023 14:52:00:INFO:FileTransferSession:worker: Awoke from deep sleep to some data 10/07/2023 14:52:00:INFO:FileTransferSession:queue_next: New limit is 4 (8/4), queueing 4 10/07/2023 14:52:00:INFO:FileTransferSession:recv_blocks: Sending ACK for block 0 10/07/2023 14:52:00:INFO:FileTransferSession:send_ack: sending ACK for blocks [0] ({'': b'\x00'}) 10/07/2023 14:52:00:INFO:FileTransferSession:worker: Session loop (4:switch.c) 10/07/2023 14:52:00:INFO:FileTransferSession:worker: Deep sleep 10/07/2023 14:52:00:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 1.6 sec before transmitting 10/07/2023 14:52:09:INFO:SessionManager:incoming: Received block 1:4 for session switch.c' 10/07/2023 14:52:09:INFO:FileTransferSession:worker: Awoke from deep sleep to some data 10/07/2023 14:52:09:INFO:FileTransferSession:queue_next: New limit is 4 (8/4), queueing 4 10/07/2023 14:52:09:INFO:FileTransferSession:recv_blocks: Got block 1 10/07/2023 14:52:09:INFO:FileTransferSession:recv_blocks: Waiting OOO blocks: [1] 10/07/2023 14:52:09:INFO:FileTransferSession:recv_blocks: Queuing now in-order block 1: DDT2+: 1:4:4 IZ2QDO->IZ2LXI-W (b'x\xdaU\xcd\xc1\n\xc20\x0c\x06\xe0{ \xef 10/07/2023 14:55:44:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:55:44:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:55:44:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:55:44:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:55:44:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:55:44:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 14:55:48:INFO:DDT2EncodedFrame:unpack: Checksum failed: 19830 != 62673 10/07/2023 14:55:48:INFO:SessionManager:incoming: Received block 0:0 for sessionchat' 10/07/2023 14:55:50:INFO:MainApp:Showing Map Window 10/07/2023 14:56:14:INFO:RPCSession:worker: Cancelling job 2 due to timeout 10/07/2023 14:56:14:INFO:RemoteFileV:_file_list_cb : Incomplete job 10/07/2023 14:56:22:INFO:SessionManager:incoming: Received block 0:0 for session chat' 10/07/2023 14:56:38:INFO:LocalFileV:refresh: Adding local fileC:\Users\mauri\Desktop\D-RATS Shared/Hello.txt' 10/07/2023 14:56:38:INFO:LocalFileV:refresh: Adding local file C:\Users\mauri\Desktop\D-RATS Shared/HelloIZ2LXI.txt' 10/07/2023 14:56:38:INFO:LocalFileV:refresh: Adding local fileC:\Users\mauri\Desktop\D-RATS Shared/newemail.wav' 10/07/2023 14:56:38:INFO:LocalFileV:refresh: Adding local file C:\Users\mauri\Desktop\D-RATS Shared/Red Alert.wav' 10/07/2023 14:56:38:INFO:LocalFileV:refresh: Adding local fileC:\Users\mauri\Desktop\D-RATS Shared/Sonar_pings.wav' 10/07/2023 14:56:38:INFO:LocalFileV:refresh: Adding local file C:\Users\mauri\Desktop\D-RATS Shared/switch.c' 10/07/2023 14:56:44:INFO:Spelling:Tested spelling okay: ['spelling,', 'spieling,', 'sapling,', 'spewing,', 'spilling,', 'spoiling,', 'spooling,', 'spline,', 'spellings,', 'pealing,', 'peeling,', 'sealing,', 'selling,', 'soling,', 'spleen,', 'sling,', 'speckling,', 'palin g,', 'piling,', 'poling,', 'puling,', 'splint,', "spelling's"] 10/07/2023 14:57:09:INFO:RPCSession:Sending jobFile list request' to IZ2QDO 10/07/2023 14:57:09:INFO:RPCSession:Job sent 10/07/2023 14:57:10:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 1.1 sec before transmitting 10/07/2023 14:57:40:INFO:RPCSession:worker: Cancelling job 3 due to timeout 10/07/2023 14:57:40:INFO:RemoteFileV:_file_list_cb : Incomplete job 10/07/2023 14:59:09:INFO:SessionManager:incoming: Received block 0:0 for session chat' 10/07/2023 15:00:48:INFO:RPCActionSet:Position request forIZ2LXI-W' 10/07/2023 15:00:48:INFO:RPCActionSet:Position Report: Self=<rpc.RPCActionSet object at 0x0000019693673d80 (d_rats+sessions+rpc+RPCActionSet at 0x0000019693c10210)> 10/07/2023 15:00:48:INFO:RPCActionSet:rpc_pos_report: port is : COM4 10/07/2023 15:00:48:INFO:RPCActionSet:rpc_pos_report: fix is: IZ2LXI-W relazione 45.8004,9.4284@0 ft at 14:49:19 10/07/2023 15:00:48:INFO:RPCActionSet:rpc_pos_report: fix in NMEA GGA is: $GPGGA,150048,4548.026,N,925.706,E,1,3,0,0,M,0,M,,51 IZ2LXI-W,BN 26

10/07/2023 15:00:48:INFO:RPCActionSet:rpc_pos_report: fix in APRS is: {'rc': 'True', 'msg': '$$CRCD781,IZ2LXI-W>APRATS,DSTAR*:/130048h4548.03N/00925.71E>\r\n'} 10/07/2023 15:00:48:INFO:SessionManager:incoming: Received block 1:0 for session rpc' 10/07/2023 15:00:48:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 1.3 sec before transmitting 10/07/2023 15:01:02:INFO:SessionManager:incoming: Received block 2:0 for sessionrpc' 10/07/2023 15:01:02:INFO:RPCSession:__job_state: Job state: complete for 2: {'version': '0.4.1.dev39-g0fe2752-dirty', 'os': "Windows 10 (10, 0, 19045, 2, '')", 'pyver': '3.10.12', 'pygtkver': 'None', 'gtkver': '3.24.38'} 10/07/2023 15:01:02:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 1.3 sec before transmitting 10/07/2023 15:01:04:INFO:SWFSerial:is_xon: Assuming IXANY behavior 10/07/2023 15:01:10:INFO:SessionManager:incoming: Received block 0:0 for session `chat' 10/07/2023 15:01:50:INFO:MainWindow:_delete handler invoked <class 'gi.overrides.Gdk.Event'> 10/07/2023 15:01:50:INFO:MainApp:Saving config... 10/07/2023 15:01:50:INFO:Transporter:send_frames: [SERIAL COM4@9600] Waiting 1.8 sec before transmitting

wb8tyw commented 1 year ago

Can you reproduce this via a Ratflector?

Looks like something in the doing a 'File List Request' is not right. To diagnose this, need to capture a "sniff" of the filelist request from a D-Rats .3 system. I do not have the ability to locally run D-Rats .3 any more.

Two systems running D-Rats can have their serial ports connected for via a null-modem cable to allow testing with out actually needing a radio connection.

However it should also be possible to use a ratflector for testing.

maurizioandreotti commented 1 year ago

Can you reproduce this via a Ratflector? In the past I had tested this and it was working. It still is: Connecting from 0.4.1.dev to an host using 0.3.9 on sttammany.ratflector.com:9000 I get the file list.

So issue happens only via RF. I did tests yesterday with 2 guys, one with 0.3.9 and one with 0.3.10beta and between them it was working correctly.

regardless of the issue we were able to TX and RX a file between 0.3 and 0.4 versions.

Il giorno dom 8 ott 2023 alle ore 01:46 John E. Malmberg < @.***> ha scritto:

Can you reproduce this via a Ratflector?

Looks like something in the doing a 'File List Request' is not right. To diagnose this, need to capture a "sniff" of the filelist request from a D-Rats .3 system. I do not have the ability to locally run D-Rats .3 any more.

Two systems running D-Rats can have their serial ports connected for via a null-modem cable to allow testing with out actually needing a radio connection.

However it should also be possible to use a ratflector for testing.

— Reply to this email directly, view it on GitHub https://github.com/ham-radio-software/D-Rats/issues/253#issuecomment-1751867065, or unsubscribe https://github.com/notifications/unsubscribe-auth/AB2W7OWQSDSNDT5QAS5HXZLX6HSV7AVCNFSM6AAAAAA5W5MGNWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTONJRHA3DOMBWGU . You are receiving this because you authored the thread.Message ID: @.***>

wb8tyw commented 1 year ago

The receive code on through the serial port has a bug in it that appears to be in the python2 version also.

The bug is as follows:

D-Rats sends data to the radio via serial port: D-Rats then goes to read data from the radio via the serial port. If the radio has not yet passed the data from the remote radio to D-Rats: BUG: part one. D-Rats does not check to see if it is an XOFF state! BUG: part two: D-Rats does not have any code to test if the radio has requested an XOFF state. D-Rats assumes that the Radio has sent an XOFF to D-Rats and waits for the radio give it a single character. BUG: part three: If the character is not an XOFF or XON character it is discarded.

The python3 code has a small bug where it logs that this character is being discarded, which is really the only difference in this code between 0.4 and 0.3.

Note that pyserial can be configured to handle the XON/XOFF transparent to D-Rats. This feature in pyserial has been explicitly disabled in D-Rats for unknown reasons. We do not know why this pyserial XON/XOFF handling was disabled. Was it ever tested?

So this code has does not work properly in either 0.3 or 0.4 versions of D-Rats.

Actions item #1: Test if pyserial xon/xoff will work. Need change the places in the code where "xonxoff=0" to "xonxoff=True". Change the broken is_xon to always return True.

Related: https://github.com/ham-radio-software/D-Rats/issues/134 https://github.com/ham-radio-software/D-Rats/issues/132