search

drowe67 / freedv-gui

GUI Application for FreeDV – open source digital voice for HF radio
https://freedv.org/
GNU Lesser General Public License v2.1
211 stars 52 forks source link

Set timeout for Hamlib comms to avoid GUI getting stuck. #745

Closed tmiw closed 1 month ago

tmiw commented 2 months ago

Resolves #742 by setting a timeout when connecting to the radio via Hamlib. Note that this requires hamlib 4.6~git to have full effect (especially with Icom radios).

barjac commented 2 months ago

Not sure if this is related but testing with this patch: If FreeDV is run and the modem started without the radio switched on there is oddly no complaint from FreeDV. The PTT can be pressed and the button goes red. The mic audio is shown on the 'scope' and the reporter indicates that the station is in TX. It is some time before any hamlib message finally appears. (around 38 seconds) It is a rather silly thing to do but probably should not be allowed to happen.

tmiw commented 2 months ago

I'm honestly not sure how the timeout stuff interacts with Hamlib exactly. What version of the latter are you running? It's possible that there may still need to be kinks worked out depending on the radio you're using (we're currently trying to get the timeout stuff working properly with Icom).

barjac commented 2 months ago

I'm honestly not sure how the timeout stuff interacts with Hamlib exactly. What version of the latter are you running?

Current git master @ #8d5256533 using rigctld.

I was using an earlier snapshot of hamlib previously from March. Now if the radio is turned off with the modem running and then back on after 10 seconds or so, hamlib successfully recovers without any lock-ups. It does now seem more robust. However starting the program and the modem without the radio switched on does allow an apparent transmission to continue for a long time without warning as reported earlier. Once a warning has displayed the first time then subsequent warnings are immediate on clicking PTT to start or stop 'TX', so it looks like its only the first warning dialogue which is delayed.

tmiw commented 2 months ago

Can you try running rigctl separately, once with -C timeout=1000 -C retry=1 -C timeout_retry=1 and once without those arguments for comparison? Does it still take 10 seconds to error out with those command arguments?

barjac commented 2 months ago

Can you try running rigctl separately, once with -C timeout=1000 -C retry=1 -C timeout_retry=1 and once without those arguments for comparison? Does it still take 10 seconds to error out with those command arguments?

Ah I see what you mean - without FreeDV in the mix? So using rigctl not rigctld.

OK I never use it that way but running the following with the radio off it takes 7 seconds for it to error out: rigctl -vvvvv -Z -m 2003 -r /dev/ttyUSB0 --set-conf=serial_handshake=None -C timeout=1000 -C retry=1 -C timeout_retry=1

If the radio is on, the connection is immediate and rigctl waits for a command. If the radio is then turned off and 'f ENTER' is given (to ask the radio for the current VFO frequ) then it takes 35 seconds for it to finally time out.

Notice all the 'Communication timed out' messages, but it soldiers onward and even: 'no response to get_id from rig...continuing anyway' :)

Rig command: f
2024-09-15T23:15:00.356412-0000: rigctl_parse: cmd=f(66) handle=0
2024-09-15T23:15:00.356447-0000: rigctl_parse: vfo_opt=0
2024-09-15T23:15:00.356468-0000: rigctl_parse.c(2136):rigctl_get_freq entered
2024-09-15T23:15:00.356488-0000: ***2:rig.c(2384):rig_get_freq entered
2024-09-15T23:15:00.356505-0000: rig_get_freq called vfo=currVFO
2024-09-15T23:15:00.356522-0000: rig_get_freq(2402) called vfo=currVFO
2024-09-15T23:15:00.356565-0000: vfo_fixup:(from rig_get_freq:2409) vfo=currVFO, vfo_curr=VFOA, split=0
2024-09-15T23:15:00.356581-0000: vfo_fixup: Leaving currVFO alone
2024-09-15T23:15:00.356595-0000: rig.c(2411) vfo=currVFO, curr_vfo=VFOA
2024-09-15T23:15:00.356666-0000: rig_get_freq: cache miss age=16667ms, cached_vfo=VFOA, asked_vfo=VFOA, use_cached_freq=0
2024-09-15T23:15:00.356680-0000: rig_get_freq(2524): vfo_opt=0, model=2003
2024-09-15T23:15:00.356694-0000: ****3:kenwood.c(2035):kenwood_get_freq entered
2024-09-15T23:15:00.356706-0000: kenwood_safe_transaction called, cmd=FA, expected=13
2024-09-15T23:15:00.356717-0000: kenwood_transaction called cmd=FA
2024-09-15T23:15:00.356729-0000: kenwood_transaction: cmdstr = FA
2024-09-15T23:15:00.356769-0000: write_block(): TX 3 bytes
2024-09-15T23:15:00.356783-0000: 0000    46 41 3b                                            FA;             
2024-09-15T23:15:02.378994-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:02.379023-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=1
2024-09-15T23:15:02.379038-0000: kenwood_transaction: cmdstr = FA
2024-09-15T23:15:02.379083-0000: write_block(): TX 3 bytes
2024-09-15T23:15:02.379101-0000: 0000    46 41 3b                                            FA;             
2024-09-15T23:15:04.399582-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:04.399614-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=1, rp->retry=1
2024-09-15T23:15:04.399631-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:04.399649-0000: kenwood.c(741):kenwood_safe_transaction returning2(-5) Communication timed out

2024-09-15T23:15:04.399667-0000: ****3:kenwood.c(2100):kenwood_get_freq returning(-5) Communication timed out

2024-09-15T23:15:04.399721-0000: rig_get_band called
2024-09-15T23:15:04.399736-0000: **2:rig_get_freq: elapsed=4043ms
2024-09-15T23:15:04.399750-0000: ***2:rig.c(2661):rig_get_freq returning(-5) Communication timed out

2024-09-15T23:15:04.399769-0000: rigctl_parse.c(2142):rigctl_get_freq returning2(-5) Communication timed out

get_freq: error = multicast_publisher: sending rig snapshot data: {"app":"Hamlib","version":"4.6~git from indeterminate source revision.","seq":22,"time":"2024-09-15T22:15:03.788747-0000","crc":0,"rig":{"id":{"model":"TS-450S","endpoint":"/dev/ttyUSB0","process":"10725","deviceId":""},"status":"OK","errorMsg":"","name":"TS-450S","split":false,"splitVfo":"None","satMode":false,"modes":["AM","CW","USB","LSB","RTTY","FM","CWR","RTTYR"]},"vfos":[{"name":"VFOA","freq":1955000,"mode":"LSB","width":2700,"ptt":false,"rx":true,"tx":true},{"name":"VFOB","freq":1839500,"mode":"","width":0,"ptt":false,"rx":false,"tx":false},{"name":"MEM","freq":0,"mode":"","width":0,"ptt":false,"rx":false,"tx":false}]}
read_string_generic(): Timed out 2.010 seconds after 0 chars, direct=1
kenwood_transaction: read_string len=0 ''
kenwood_transaction: read_string retval < 0, retval = -5, retry_read=1, rp->retry=1
kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

kenwood.c(741):kenwood_safe_transaction returning2(-5) Communication timed out

****3:kenwood.c(2100):kenwood_get_freq returning(-5) Communication timed out

rig_get_freq(2544): freqMainA=1955000, modeMainA=LSB, widthMainA=2700
rig_get_freq(2544): freqMainB=1839500, modeMainB=, widthMainB=0
rig_set_cache_freq(167):  vfo=VFOA, current_vfo=VFOA
rig_get_band called
**2:rig_get_freq: elapsed=4043ms
***2:rig.c(2661):rig_get_freq returning(-5) Communication timed out

rigctl_parse.c(2142):rigctl_get_freq returning2(-5) Communication timed out

Communication timed out

2024-09-15T23:15:04.399858-0000: ***2:rig.c(6782):rig_get_powerstat entered
2024-09-15T23:15:04.399871-0000: **rig.c(6796) trace
2024-09-15T23:15:04.399882-0000: ****3:kenwood.c(5200):kenwood_get_powerstat entered
2024-09-15T23:15:04.399892-0000: ****3:kenwood.c(5205):kenwood_get_powerstat returning(0) 
2024-09-15T23:15:04.399903-0000: ***2:rig.c(6809):rig_get_powerstat returning(0) 
2024-09-15T23:15:04.399914-0000: main: i/o error
2024-09-15T23:15:04.399925-0000: ***2:rig.c(1645):rig_close entered
2024-09-15T23:15:04.399937-0000: ****3:rig.c(8413):morse_data_handler_stop entered
2024-09-15T23:15:04.600069-0000: ****3:rig.c(8459):morse_data_handler_stop returning(0) 
2024-09-15T23:15:04.600099-0000: ****3:rig.c(8372):async_data_handler_stop entered
2024-09-15T23:15:04.600109-0000: ****3:rig.c(8403):async_data_handler_stop returning(0) 
2024-09-15T23:15:04.600120-0000: ****3:event.c(327):rig_poll_routine_stop entered
2024-09-15T23:15:04.639390-0000: event.c(253): Stopping rig poll routine thread
2024-09-15T23:15:04.639458-0000: ****3:event.c(362):rig_poll_routine_stop returning(0) 
2024-09-15T23:15:04.639491-0000: ****3:network.c(1871):network_multicast_receiver_stop entered
2024-09-15T23:15:04.639583-0000: multicast_receiver(1463): pselect signal
2024-09-15T23:15:04.639597-0000: network.c(1524): Stopped multicast receiver
2024-09-15T23:15:04.639700-0000: ****3:network.c(1916):network_multicast_receiver_stop returning(0) 
2024-09-15T23:15:04.639723-0000: ****3:network.c(1703):network_multicast_publisher_stop entered
2024-09-15T23:15:04.739752-0000: network.c(1071): Stopped multicast publisher
2024-09-15T23:15:04.739908-0000: ****3:network.c(1742):network_multicast_publisher_stop returning(0) 
2024-09-15T23:15:04.739938-0000: ****3:kenwood.c(1143):kenwood_close entered
2024-09-15T23:15:04.739953-0000: ****3:kenwood.c(1145):kenwood_close returning(0) 
2024-09-15T23:15:04.739973-0000: ser_close: restoring options
2024-09-15T23:15:04.748782-0000: rig_close(1789): 0x20ce71d4 rs->comm_state==0?=0
2024-09-15T23:15:04.748811-0000: ***2:rig.c(1793):rig_close returning(0) 
2024-09-15T23:15:05.748903-0000: main: rig_close retcode=0
2024-09-15T23:15:05.748943-0000: rig.c(945):rig_open entered
2024-09-15T23:15:05.748971-0000: rig_settings_get_path: path=/home/baz/.config/hamlib_settings
2024-09-15T23:15:05.748988-0000: rig_settings_load_all: settings_file (/home/baz/.config/hamlib_settings): No such file or directory
2024-09-15T23:15:05.748996-0000: rig_open: cwd=/home/baz
2024-09-15T23:15:05.749038-0000: rig_open: /home/baz/hamlib_settings No such file or directory
2024-09-15T23:15:05.749051-0000: rig_open: async_data_enable=0, async_data_supported=0
2024-09-15T23:15:05.749064-0000: serial_open: /dev/ttyUSB0
2024-09-15T23:15:05.750962-0000: serial_setup: tcgetattr
2024-09-15T23:15:05.750990-0000: serial_setup: cfmakeraw
2024-09-15T23:15:05.751003-0000: serial_setup: cfsetispeed=4800,0x000c
2024-09-15T23:15:05.751014-0000: serial_setup: cfsetospeed=4800,0x000c
2024-09-15T23:15:05.751026-0000: serial_setup: data_bits=8
2024-09-15T23:15:05.751036-0000: serial_setup: stopbits=2
2024-09-15T23:15:05.751045-0000: serial_setup: parity=0
2024-09-15T23:15:05.751056-0000: serial_setup: Handshake=None
2024-09-15T23:15:05.751068-0000: serial_setup: tcsetattr TCSANOW
2024-09-15T23:15:05.802186-0000: ***2:rig.c(8287):async_data_handler_start entered
2024-09-15T23:15:05.802204-0000: async_data_handler_start: async data support disabled since async_data_enabled=0
2024-09-15T23:15:05.802211-0000: ***2:rig.c(8294):async_data_handler_start returning(0) 
2024-09-15T23:15:05.802218-0000: rig_open: 0x20ce71d4 rs->comm_state==1?=1
2024-09-15T23:15:05.902255-0000: ***2:rig.c(6782):rig_get_powerstat entered
2024-09-15T23:15:05.902273-0000: **rig.c(6796) trace
2024-09-15T23:15:05.902278-0000: ****3:kenwood.c(5200):kenwood_get_powerstat entered
2024-09-15T23:15:05.902283-0000: ****3:kenwood.c(5205):kenwood_get_powerstat returning(0) 
2024-09-15T23:15:05.902287-0000: ***2:rig.c(6809):rig_get_powerstat returning(0) 
2024-09-15T23:15:05.902302-0000: ***2:kenwood.c(896):kenwood_open entered
2024-09-15T23:15:05.902306-0000: ****3:kenwood.c(1172):kenwood_get_id entered
2024-09-15T23:15:05.902311-0000: kenwood_transaction called cmd=ID
2024-09-15T23:15:05.902316-0000: kenwood_transaction: cmdstr = ID
2024-09-15T23:15:05.902359-0000: write_block(): TX 3 bytes
2024-09-15T23:15:05.902375-0000: 0000    49 44 3b                                            ID;             
2024-09-15T23:15:07.923830-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:07.923861-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:07.923867-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:07.923872-0000: ****3:kenwood.c(1179):kenwood_get_id returning(-5) Communication timed out

2024-09-15T23:15:08.123930-0000: ****3:kenwood.c(1172):kenwood_get_id entered
2024-09-15T23:15:08.123959-0000: kenwood_transaction called cmd=ID
2024-09-15T23:15:08.123971-0000: kenwood_transaction: cmdstr = ID
2024-09-15T23:15:08.124013-0000: write_block(): TX 3 bytes
2024-09-15T23:15:08.124026-0000: 0000    49 44 3b                                            ID;             
2024-09-15T23:15:10.145667-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:10.145694-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:10.145714-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:10.145719-0000: ****3:kenwood.c(1179):kenwood_get_id returning(-5) Communication timed out

2024-09-15T23:15:10.145737-0000: kenwood_open: no response to get_id from rig...continuing anyway
2024-09-15T23:15:10.145754-0000: kenwood_transaction called cmd=FA
2024-09-15T23:15:10.145759-0000: kenwood_transaction: cmdstr = FA
2024-09-15T23:15:10.145779-0000: write_block(): TX 3 bytes
2024-09-15T23:15:10.145786-0000: 0000    46 41 3b                                            FA;             
2024-09-15T23:15:12.167167-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:12.167193-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:12.167214-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:12.167219-0000: kenwood_open: no response from rig
2024-09-15T23:15:12.167224-0000: ***2:kenwood.c(1009):kenwood_open returning(-5) Communication timed out

2024-09-15T23:15:12.167242-0000: ***2:rig.c(8372):async_data_handler_stop entered
2024-09-15T23:15:12.167247-0000: ***2:rig.c(8403):async_data_handler_stop returning(0) 
2024-09-15T23:15:12.167252-0000: ***2:rig.c(8413):morse_data_handler_stop entered
2024-09-15T23:15:12.367366-0000: ***2:rig.c(8459):morse_data_handler_stop returning(0) 
2024-09-15T23:15:12.367397-0000: ser_close: restoring options
2024-09-15T23:15:12.373235-0000: rig.c(1457):rig_open returning2(-5) Communication timed out

2024-09-15T23:15:12.373259-0000: main: rig_open retcode=-5
2024-09-15T23:15:12.373272-0000: ***2:rig.c(1645):rig_close entered
2024-09-15T23:15:12.373282-0000: ***2:rig.c(1653):rig_close returning(-1) Invalid parameter

2024-09-15T23:15:13.373358-0000: main: rig_close retcode=-1
2024-09-15T23:15:13.373388-0000: rig.c(945):rig_open entered
2024-09-15T23:15:13.373417-0000: rig_settings_get_path: path=/home/baz/.config/hamlib_settings
2024-09-15T23:15:13.373448-0000: rig_settings_load_all: settings_file (/home/baz/.config/hamlib_settings): No such file or directory
2024-09-15T23:15:13.373465-0000: rig_open: cwd=/home/baz
2024-09-15T23:15:13.373483-0000: rig_open: /home/baz/hamlib_settings No such file or directory
2024-09-15T23:15:13.373494-0000: rig_open: async_data_enable=0, async_data_supported=0
2024-09-15T23:15:13.373506-0000: serial_open: /dev/ttyUSB0
2024-09-15T23:15:13.375506-0000: serial_setup: tcgetattr
2024-09-15T23:15:13.375534-0000: serial_setup: cfmakeraw
2024-09-15T23:15:13.375547-0000: serial_setup: cfsetispeed=4800,0x000c
2024-09-15T23:15:13.375557-0000: serial_setup: cfsetospeed=4800,0x000c
2024-09-15T23:15:13.375568-0000: serial_setup: data_bits=8
2024-09-15T23:15:13.375578-0000: serial_setup: stopbits=2
2024-09-15T23:15:13.375588-0000: serial_setup: parity=0
2024-09-15T23:15:13.375596-0000: serial_setup: Handshake=None
2024-09-15T23:15:13.375609-0000: serial_setup: tcsetattr TCSANOW
2024-09-15T23:15:13.426670-0000: ***2:rig.c(8287):async_data_handler_start entered
2024-09-15T23:15:13.426693-0000: async_data_handler_start: async data support disabled since async_data_enabled=0
2024-09-15T23:15:13.426704-0000: ***2:rig.c(8294):async_data_handler_start returning(0) 
2024-09-15T23:15:13.426715-0000: rig_open: 0x20ce71d4 rs->comm_state==1?=1
2024-09-15T23:15:13.526781-0000: ***2:rig.c(6782):rig_get_powerstat entered
2024-09-15T23:15:13.526810-0000: **rig.c(6796) trace
2024-09-15T23:15:13.526828-0000: ****3:kenwood.c(5200):kenwood_get_powerstat entered
2024-09-15T23:15:13.526833-0000: ****3:kenwood.c(5205):kenwood_get_powerstat returning(0) 
2024-09-15T23:15:13.526837-0000: ***2:rig.c(6809):rig_get_powerstat returning(0) 
2024-09-15T23:15:13.526843-0000: ***2:kenwood.c(896):kenwood_open entered
2024-09-15T23:15:13.526865-0000: ****3:kenwood.c(1172):kenwood_get_id entered
2024-09-15T23:15:13.526870-0000: kenwood_transaction called cmd=ID
2024-09-15T23:15:13.526875-0000: kenwood_transaction: cmdstr = ID
2024-09-15T23:15:13.526907-0000: write_block(): TX 3 bytes
2024-09-15T23:15:13.526921-0000: 0000    49 44 3b                                            ID;             
2024-09-15T23:15:15.549125-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:15.549149-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:15.549168-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:15.549173-0000: ****3:kenwood.c(1179):kenwood_get_id returning(-5) Communication timed out

2024-09-15T23:15:15.749223-0000: ****3:kenwood.c(1172):kenwood_get_id entered
2024-09-15T23:15:15.749255-0000: kenwood_transaction called cmd=ID
2024-09-15T23:15:15.749266-0000: kenwood_transaction: cmdstr = ID
2024-09-15T23:15:15.749308-0000: write_block(): TX 3 bytes
2024-09-15T23:15:15.749314-0000: 0000    49 44 3b                                            ID;             
2024-09-15T23:15:17.771575-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:17.771603-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:17.771609-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:17.771615-0000: ****3:kenwood.c(1179):kenwood_get_id returning(-5) Communication timed out

2024-09-15T23:15:17.771620-0000: kenwood_open: no response to get_id from rig...continuing anyway
2024-09-15T23:15:17.771625-0000: kenwood_transaction called cmd=FA
2024-09-15T23:15:17.771629-0000: kenwood_transaction: cmdstr = FA
2024-09-15T23:15:17.771657-0000: write_block(): TX 3 bytes
2024-09-15T23:15:17.771671-0000: 0000    46 41 3b                                            FA;             
2024-09-15T23:15:19.793918-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:19.793965-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:19.793981-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:19.793994-0000: kenwood_open: no response from rig
2024-09-15T23:15:19.794007-0000: ***2:kenwood.c(1009):kenwood_open returning(-5) Communication timed out

2024-09-15T23:15:19.794020-0000: ***2:rig.c(8372):async_data_handler_stop entered
2024-09-15T23:15:19.794032-0000: ***2:rig.c(8403):async_data_handler_stop returning(0) 
2024-09-15T23:15:19.794043-0000: ***2:rig.c(8413):morse_data_handler_stop entered
2024-09-15T23:15:19.994119-0000: ***2:rig.c(8459):morse_data_handler_stop returning(0) 
2024-09-15T23:15:19.994150-0000: ser_close: restoring options
2024-09-15T23:15:19.999804-0000: rig.c(1457):rig_open returning2(-5) Communication timed out

2024-09-15T23:15:19.999829-0000: main: rig_open retcode=-5
2024-09-15T23:15:19.999847-0000: ***2:rig.c(1645):rig_close entered
2024-09-15T23:15:19.999852-0000: ***2:rig.c(1653):rig_close returning(-1) Invalid parameter

2024-09-15T23:15:20.999885-0000: main: rig_close retcode=-1
2024-09-15T23:15:20.999912-0000: rig.c(945):rig_open entered
2024-09-15T23:15:20.999937-0000: rig_settings_get_path: path=/home/baz/.config/hamlib_settings
2024-09-15T23:15:20.999954-0000: rig_settings_load_all: settings_file (/home/baz/.config/hamlib_settings): No such file or directory
2024-09-15T23:15:20.999962-0000: rig_open: cwd=/home/baz
2024-09-15T23:15:20.999971-0000: rig_open: /home/baz/hamlib_settings No such file or directory
2024-09-15T23:15:20.999978-0000: rig_open: async_data_enable=0, async_data_supported=0
2024-09-15T23:15:20.999984-0000: serial_open: /dev/ttyUSB0
2024-09-15T23:15:20.001617-0000: serial_setup: tcgetattr
2024-09-15T23:15:20.001646-0000: serial_setup: cfmakeraw
2024-09-15T23:15:20.001661-0000: serial_setup: cfsetispeed=4800,0x000c
2024-09-15T23:15:20.001674-0000: serial_setup: cfsetospeed=4800,0x000c
2024-09-15T23:15:20.001684-0000: serial_setup: data_bits=8
2024-09-15T23:15:20.001694-0000: serial_setup: stopbits=2
2024-09-15T23:15:20.001704-0000: serial_setup: parity=0
2024-09-15T23:15:20.001714-0000: serial_setup: Handshake=None
2024-09-15T23:15:20.001726-0000: serial_setup: tcsetattr TCSANOW
2024-09-15T23:15:21.052806-0000: ***2:rig.c(8287):async_data_handler_start entered
2024-09-15T23:15:21.052819-0000: async_data_handler_start: async data support disabled since async_data_enabled=0
2024-09-15T23:15:21.052824-0000: ***2:rig.c(8294):async_data_handler_start returning(0) 
2024-09-15T23:15:21.052829-0000: rig_open: 0x20ce71d4 rs->comm_state==1?=1
2024-09-15T23:15:21.152879-0000: ***2:rig.c(6782):rig_get_powerstat entered
2024-09-15T23:15:21.152907-0000: **rig.c(6796) trace
2024-09-15T23:15:21.152918-0000: ****3:kenwood.c(5200):kenwood_get_powerstat entered
2024-09-15T23:15:21.152928-0000: ****3:kenwood.c(5205):kenwood_get_powerstat returning(0) 
2024-09-15T23:15:21.152938-0000: ***2:rig.c(6809):rig_get_powerstat returning(0) 
2024-09-15T23:15:21.152952-0000: ***2:kenwood.c(896):kenwood_open entered
2024-09-15T23:15:21.152964-0000: ****3:kenwood.c(1172):kenwood_get_id entered
2024-09-15T23:15:21.152971-0000: kenwood_transaction called cmd=ID
2024-09-15T23:15:21.152984-0000: kenwood_transaction: cmdstr = ID
2024-09-15T23:15:21.153017-0000: write_block(): TX 3 bytes
2024-09-15T23:15:21.153023-0000: 0000    49 44 3b                                            ID;             
2024-09-15T23:15:23.175226-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:23.175253-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:23.175266-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:23.175278-0000: ****3:kenwood.c(1179):kenwood_get_id returning(-5) Communication timed out

2024-09-15T23:15:23.375353-0000: ****3:kenwood.c(1172):kenwood_get_id entered
2024-09-15T23:15:23.375383-0000: kenwood_transaction called cmd=ID
2024-09-15T23:15:23.375395-0000: kenwood_transaction: cmdstr = ID
2024-09-15T23:15:23.375435-0000: write_block(): TX 3 bytes
2024-09-15T23:15:23.375449-0000: 0000    49 44 3b                                            ID;             
2024-09-15T23:15:25.397642-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:25.397669-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:25.397683-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:25.397695-0000: ****3:kenwood.c(1179):kenwood_get_id returning(-5) Communication timed out

2024-09-15T23:15:25.397708-0000: kenwood_open: no response to get_id from rig...continuing anyway
2024-09-15T23:15:25.397720-0000: kenwood_transaction called cmd=FA
2024-09-15T23:15:25.397733-0000: kenwood_transaction: cmdstr = FA
2024-09-15T23:15:25.397770-0000: write_block(): TX 3 bytes
2024-09-15T23:15:25.397783-0000: 0000    46 41 3b                                            FA;             
2024-09-15T23:15:27.419993-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:27.420020-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:27.420033-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:27.420044-0000: kenwood_open: no response from rig
2024-09-15T23:15:27.420056-0000: ***2:kenwood.c(1009):kenwood_open returning(-5) Communication timed out

2024-09-15T23:15:27.420068-0000: ***2:rig.c(8372):async_data_handler_stop entered
2024-09-15T23:15:27.420078-0000: ***2:rig.c(8403):async_data_handler_stop returning(0) 
2024-09-15T23:15:27.420088-0000: ***2:rig.c(8413):morse_data_handler_stop entered
2024-09-15T23:15:27.620190-0000: ***2:rig.c(8459):morse_data_handler_stop returning(0) 
2024-09-15T23:15:27.620220-0000: ser_close: restoring options
2024-09-15T23:15:27.625944-0000: rig.c(1457):rig_open returning2(-5) Communication timed out

2024-09-15T23:15:27.625969-0000: main: rig_open retcode=-5
2024-09-15T23:15:27.625982-0000: ***2:rig.c(1645):rig_close entered
2024-09-15T23:15:27.625993-0000: ***2:rig.c(1653):rig_close returning(-1) Invalid parameter

2024-09-15T23:15:28.626075-0000: main: rig_close retcode=-1
2024-09-15T23:15:28.626092-0000: rig.c(945):rig_open entered
2024-09-15T23:15:28.626107-0000: rig_settings_get_path: path=/home/baz/.config/hamlib_settings
2024-09-15T23:15:28.626138-0000: rig_settings_load_all: settings_file (/home/baz/.config/hamlib_settings): No such file or directory
2024-09-15T23:15:28.626146-0000: rig_open: cwd=/home/baz
2024-09-15T23:15:28.626171-0000: rig_open: /home/baz/hamlib_settings No such file or directory
2024-09-15T23:15:28.626177-0000: rig_open: async_data_enable=0, async_data_supported=0
2024-09-15T23:15:28.626183-0000: serial_open: /dev/ttyUSB0
2024-09-15T23:15:28.628098-0000: serial_setup: tcgetattr
2024-09-15T23:15:28.628121-0000: serial_setup: cfmakeraw
2024-09-15T23:15:28.628127-0000: serial_setup: cfsetispeed=4800,0x000c
2024-09-15T23:15:28.628135-0000: serial_setup: cfsetospeed=4800,0x000c
2024-09-15T23:15:28.628142-0000: serial_setup: data_bits=8
2024-09-15T23:15:28.628147-0000: serial_setup: stopbits=2
2024-09-15T23:15:28.628151-0000: serial_setup: parity=0
2024-09-15T23:15:28.628156-0000: serial_setup: Handshake=None
2024-09-15T23:15:28.628161-0000: serial_setup: tcsetattr TCSANOW
2024-09-15T23:15:28.679408-0000: ***2:rig.c(8287):async_data_handler_start entered
2024-09-15T23:15:28.679432-0000: async_data_handler_start: async data support disabled since async_data_enabled=0
2024-09-15T23:15:28.679443-0000: ***2:rig.c(8294):async_data_handler_start returning(0) 
2024-09-15T23:15:28.679454-0000: rig_open: 0x20ce71d4 rs->comm_state==1?=1
2024-09-15T23:15:28.779521-0000: ***2:rig.c(6782):rig_get_powerstat entered
2024-09-15T23:15:28.779551-0000: **rig.c(6796) trace
2024-09-15T23:15:28.779562-0000: ****3:kenwood.c(5200):kenwood_get_powerstat entered
2024-09-15T23:15:28.779572-0000: ****3:kenwood.c(5205):kenwood_get_powerstat returning(0) 
2024-09-15T23:15:28.779585-0000: ***2:rig.c(6809):rig_get_powerstat returning(0) 
2024-09-15T23:15:28.779596-0000: ***2:kenwood.c(896):kenwood_open entered
2024-09-15T23:15:28.779606-0000: ****3:kenwood.c(1172):kenwood_get_id entered
2024-09-15T23:15:28.779617-0000: kenwood_transaction called cmd=ID
2024-09-15T23:15:28.779637-0000: kenwood_transaction: cmdstr = ID
2024-09-15T23:15:28.779679-0000: write_block(): TX 3 bytes
2024-09-15T23:15:28.779692-0000: 0000    49 44 3b                                            ID;             
2024-09-15T23:15:30.801880-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:30.801907-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:30.801919-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:30.801932-0000: ****3:kenwood.c(1179):kenwood_get_id returning(-5) Communication timed out

2024-09-15T23:15:30.002004-0000: ****3:kenwood.c(1172):kenwood_get_id entered
2024-09-15T23:15:30.002037-0000: kenwood_transaction called cmd=ID
2024-09-15T23:15:30.002048-0000: kenwood_transaction: cmdstr = ID
2024-09-15T23:15:30.002092-0000: write_block(): TX 3 bytes
2024-09-15T23:15:30.002111-0000: 0000    49 44 3b                                            ID;             
2024-09-15T23:15:33.024304-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:33.024332-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:33.024349-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:33.024354-0000: ****3:kenwood.c(1179):kenwood_get_id returning(-5) Communication timed out

2024-09-15T23:15:33.024369-0000: kenwood_open: no response to get_id from rig...continuing anyway
2024-09-15T23:15:33.024383-0000: kenwood_transaction called cmd=FA
2024-09-15T23:15:33.024389-0000: kenwood_transaction: cmdstr = FA
2024-09-15T23:15:33.024410-0000: write_block(): TX 3 bytes
2024-09-15T23:15:33.024425-0000: 0000    46 41 3b                                            FA;             
2024-09-15T23:15:35.046093-0000: kenwood_transaction: read_string len=0 ''
2024-09-15T23:15:35.046128-0000: kenwood_transaction: read_string retval < 0, retval = -5, retry_read=0, rp->retry=0
2024-09-15T23:15:35.046134-0000: kenwood.c(689):kenwood_transaction returning2(-5) Communication timed out

2024-09-15T23:15:35.046140-0000: kenwood_open: no response from rig
2024-09-15T23:15:35.046154-0000: ***2:kenwood.c(1009):kenwood_open returning(-5) Communication timed out

2024-09-15T23:15:35.046160-0000: ***2:rig.c(8372):async_data_handler_stop entered
2024-09-15T23:15:35.046165-0000: ***2:rig.c(8403):async_data_handler_stop returning(0) 
2024-09-15T23:15:35.046170-0000: ***2:rig.c(8413):morse_data_handler_stop entered
2024-09-15T23:15:35.246244-0000: ***2:rig.c(8459):morse_data_handler_stop returning(0) 
2024-09-15T23:15:35.246275-0000: ser_close: restoring options
2024-09-15T23:15:35.252195-0000: rig.c(1457):rig_open returning2(-5) Communication timed out

2024-09-15T23:15:35.252220-0000: main: rig_open retcode=-5
2024-09-15T23:15:35.252233-0000: ***2:rig.c(1645):rig_close entered
2024-09-15T23:15:35.252244-0000: ***2:rig.c(1653):rig_close returning(-1) Invalid parameter

2024-09-15T23:15:35.252262-0000: ***2:kenwood.c(879):kenwood_cleanup entered
2024-09-15T23:15:35.252274-0000: ***2:kenwood.c(884):kenwood_cleanup returning(0) 
[baz@jackodesktop ~]$

With those same extra parameters set in the rigctld.service systemd unit file with the service enabled, launching FreeDV and hitting PTT with the radio turned off, it takes 55 seconds before any error message appears in FreeDV. After that hitting the PTT button (to either start or stop TX) causes the hamlib error to appear instantly.

So no change as far as I can tell.

tmiw commented 2 months ago

Yeah, this seems like a Hamlib problem. Maybe @mdblack98 has an idea? It's also possible that I'm misunderstanding the exact meaning of timeout/retry_timeout/retry (for example, maybe timeout isn't actually in milliseconds or something).

mdblack98 commented 2 months ago

Notice the message: kenwood_open: no response to get_id from rig...continuing anyway It keeps trying. Starting things with the rig off is not supported very well as we have to allow for all sorts of vagaries with Kenwood rigs and simulators. So the old "doctor it hurts when I do this" get the pat answer "then don't do that".

tmiw commented 2 months ago

Notice the message: kenwood_open: no response to get_id from rig...continuing anyway It keeps trying. Starting things with the rig off is not supported very well as we have to allow for all sorts of vagaries with Kenwood rigs and simulators. So the old "doctor it hurts when I do this" get the pat answer "then don't do that".

Fair enough. I'm not sure how this could be checked for on my side, either, come to think of it.

barjac commented 2 months ago

Notice the message: kenwood_open: no response to get_id from rig...continuing anyway It keeps trying. Starting things with the rig off is not supported very well as we have to allow for all sorts of vagaries with Kenwood rigs and simulators. So the old "doctor it hurts when I do this" get the pat answer "then don't do that".

Fair enough. I'm not sure how this could be checked for on my side, either, come to think of it.

OK yes, I did say "It is a rather silly thing to do but probably should not be allowed to happen." however if we can't stop it happening then "don't do that!" is enough :)

tmiw commented 1 month ago

I'm guessing no updates here? Considering just merging this since in theory it shouldn't impact anything if there's actually a radio on the other end.

barjac commented 1 month ago

I'm guessing no updates here? Considering just merging this since in theory it shouldn't impact anything if there's actually a radio on the other end.

Unless there is a way to intercept the "Communication timed out' messages and after maybe two or three pop up a query asking if the radio is turned on?

Otherwise don't worry about it.