[Hamlib-developer] timeout for port_select in iofunc.c

[Kenichi A. <as...@is...>]

When I use rigctl to connect to my FT-980S, it times out at the first
read_block_generic().  (The log I got when I executed:

    rigctl -m 1031 -r /dev/tty.usbserial-10 -vvvvv

is attached below.)  If I replace the line:

https://github.com/Hamlib/Hamlib/blob/master/src/iofunc.c#L744

from:

result = port_select(p, fd + 1, &rfds, NULL, &efds, &tv, 1);

to:

result = port_select(p, fd + 1, &rfds, NULL, &efds, NULL, 1);

and recompile rigctl, I can communicate with FT-980S with the above
command successfully.  Since the port_select function eventually
expands to select function, the change effectively removes the timeout
of select.  However, even if I set the timeout long enough by passing,
e.g., "-C timeout=10000" option to rigctl, the original rigctl still
times out.  Any idea why this happens?

I am using Hamlib 4.5.2 installed via homebrew on M1 mac (Big Sur).

-- 
Kenichi Asai


$ rigctl -m 1031 -r /dev/tty.usbserial-10 -vvvvv
rigctl.c(445) Startup: rigctl -m 1031 -r /dev/tty.usbserial-10 -vvvvv
rigctl Hamlib 4.5.2 Fri Dec 23 23:04:12 2022 +0000 SHA=f12ac6
Report bugs to <ham...@li...>

rig_check_rig_caps: p1=0x100f02d20, p2=0x100f092a0, rig_model=0x100f02d20, macro_name=0x100f092a0
yaesu: initrigs4_yaesu called
rig_init: rig_model=Yaesu FT-980
rig_init: backend for FT-980 does not contain hamlib_check_rig_caps
rig_init: rig has VFO_SUB
rig_init: rig has VFO_MAIN
rig_init: rig has VFO_MEM
ft980_init called
 1:rig.c(812):rig_open entered
rig_settings_get_path: path=/Users/asai/.config/hamlib_settings
rig_settings_load_all: settings_file (/Users/asai/.config/hamlib_settings): No such file or directory
rig_open: cwd=/Users/asai
rig_open: /Users/asai/hamlib_settings does not exist
rig_open: async_data_enable=0, async_data_supported=0
serial_open: /dev/tty.usbserial-10
ser_set_rts: RTS=0
ser_set_dtr: DTR=0
serial_setup: tcgetattr
serial_setup: cfmakeraw
serial_setup: cfsetispeed=4800,0x12c0
serial_setup: cfsetospeed=4800,0x12c0
serial_setup: data_bits=8
serial_setup: parity=0
serial_setup: Handshake=None
serial_setup: tcsetattr TCSANOW
read_string_generic called, rxmax=4095 direct=1, expected_len=1
ser_set_rts: RTS=0
  2:rig.c(7417):async_data_handler_start entered
async_data_handler_start: async data support disabled since async_data_enabled=0
  2:rig.c(7424):async_data_handler_start returning(0) 
rig.c(254):add_opened_rig returning2(0) 
rig_open: 0x13600ce1c rs->comm_state==1?=1
ft980_open called
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5024 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5034 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 0b                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5054 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5005 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5036 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 0b                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.4996 seconds after 0 chars, direct=1
rig.c(1275) trace
  2:rig.c(2879):rig_get_vfo entered
rig_get_vfo: cache check age=1000000ms
rig_get_vfo: cache miss age=1000000ms
rig.c(2921) trace
ft980_get_vfo called
ft980_get_status_data called
rig_check_cache_timeout called
rig_check_cache_timeout: forced cache timeout
ft980_transaction called
rig_flush: called for serial device
read_string_generic called, rxmax=4095 direct=1, expected_len=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 01                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5003 seconds after 0 chars, direct=1
rig_get_vfo: returning -5(read_block_generic called, direct=1
read_block_generic(): Timed out 2.4996 seconds after 0 chars, direct=1
rig.c(1275) trace
  2:rig.c(2879):rig_get_vfo entered
rig_get_vfo: cache check age=1000000ms
rig_get_vfo: cache miss age=1000000ms
rig.c(2921) trace
ft980_get_vfo called
ft980_get_status_data called
rig_check_cache_timeout called
rig_check_cache_timeout: forced cache timeout
ft980_transaction called
rig_flush: called for serial device
read_string_generic called, rxmax=4095 direct=1, expected_len=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 01                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5003 seconds after 0 chars, direct=1
Communication timed out
Communication timed out
)
  2:rig_get_vfo: elapsed=2435ms
  2:rig.c(2942):rig_get_vfo returning(-5) Communication timed out

rig_open: vfo_curr=currVFO, tx_vfo=TX
rig_open: default vfo = currVFO
rig_get_freq(1985) called vfo=VFOA
vfo_fixup:(from rig_get_freq:1991) vfo=VFOA, vfo_curr=currVFO, split=0
rig.c(1994) vfo=Main, curr_vfo=currVFO
rig_get_freq: cache miss age=1000000ms, cached_vfo=Main, asked_vfo=Main, use_cached_freq=0
rig_get_freq(2081): vfo_opt=0, model=1031
ft980_get_freq: called
  ft980_get_freq: passed vfo = 0x4000000
ft980_get_status_data called
rig_check_cache_timeout called
rig_check_cache_timeout: forced cache timeout
ft980_transaction called
rig_flush: called for serial device
read_string_generic called, rxmax=4095 direct=1, expected_len=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 01                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.4996 seconds after 0 chars, direct=1
 1:rig_get_freq: elapsed=2436ms
 1:rig.c(1370):rig_open returning(0) 
Opened rig model 1031, 'FT-980'
Backend version: 20200114.0, Status: Stable
rigctl_parse: called, interactive=1

Rig command: m
rigctl_parse: input_line: m
rigctl_parse: vfo_opt=0
 1:rigctl_parse.c(2237):rigctl_get_mode entered
  2:rig.c(2404):rig_get_mode entered
vfo_fixup:(from rig_get_mode:2427) vfo=currVFO, vfo_curr=currVFO, split=0
vfo_fixup: Leaving currVFO alone
rig_get_mode: currVFO cache check age=8325ms
rig_get_mode: cache miss age mode=8325ms, width=8325ms
rig.c(2475) trace
ft980_get_mode: called
  ft980_get_mode: passed vfo = 0x20000000
ft980_get_status_data called
rig_check_cache_timeout called
rig_check_cache_timeout: forced cache timeout
ft980_transaction called
rig_flush: called for serial device
read_string_generic called, rxmax=4095 direct=1, expected_len=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 01                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5063 seconds after 0 chars, direct=1
rig_get_mode: retcode after get_mode=-5
   3:cache.c(35):rig_set_cache_mode entered
   3:cache.c(108):rig_set_cache_mode returning(0) 
  2:rig_get_mode: elapsed=2432ms
  2:rig.c(2537):rig_get_mode returning(-5) Communication timed out

 1:rigctl_parse.c(2243):rigctl_get_mode returning(-5) Communication timed out

get_mode: error = 0000    00 00 00 00 01                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5063 seconds after 0 chars, direct=1
rig_get_mode: retcode after get_mode=-5
rig_get_mode(2479): freqMainA=0, modeMainA=, widthMainA=0
rig_get_mode(2479): freqMainB=0, modeMainB=, widthMainB=0
   3:cache.c(35):rig_set_cache_mode entered
rig_set_cache_mode(37): freqMainA=0, modeMainA=, widthMainA=0
rig_set_cache_mode(37): freqMainB=0, modeMainB=, widthMainB=0
rig_set_cache_mode(107): freqMainA=0, modeMainA=, widthMainA=0
rig_set_cache_mode(107): freqMainB=0, modeMainB=, widthMainB=0
   3:cache.c(108):rig_set_cache_mode returning(0) 
rig_get_mode(2534): freqMainA=0, modeMainA=, widthMainA=0
rig_get_mode(2534): freqMainB=0, modeMainB=, widthMainB=0
  2:rig_get_mode: elapsed=2432ms
  2:rig.c(2537):rig_get_mode returning(-5) Communication timed out

 1:rigctl_parse.c(2243):rigctl_get_mode returning(-5) Communication timed out

Communication timed out

main: i/o error
 1:rig.c(1392):rig_close entered
ft980_close called
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.4213 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5015 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5049 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.4994 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 0b                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.1516 seconds after 0 chars, direct=1
  2:rig.c(7461):async_data_handler_stop entered
  2:rig.c(7491):async_data_handler_stop returning(0) 
ser_set_rts: RTS=0
ser_close: restoring options
rig_close(1528): 0x13600ce1c rs->comm_state==0?=0
 1:rig.c(1530):rig_close returning(0) 
main: rig_close retcode=0
 1:rig.c(812):rig_open entered
rig_settings_get_path: path=/Users/asai/.config/hamlib_settings
rig_settings_load_all: settings_file (/Users/asai/.config/hamlib_settings): No such file or directory
rig_open: cwd=/Users/asai
rig_open: /Users/asai/hamlib_settings does not exist
rig_open: async_data_enable=0, async_data_supported=0
serial_open: /dev/tty.usbserial-10
ser_set_rts: RTS=0
ser_set_dtr: DTR=0
serial_setup: tcgetattr
serial_setup: cfmakeraw
serial_setup: cfsetispeed=4800,0x12c0
serial_setup: cfsetospeed=4800,0x12c0
serial_setup: data_bits=8
serial_setup: parity=0
serial_setup: Handshake=None
serial_setup: tcsetattr TCSANOW
read_string_generic called, rxmax=4095 direct=1, expected_len=1
ser_set_rts: RTS=0
  2:rig.c(7417):async_data_handler_start entered
async_data_handler_start: async data support disabled since async_data_enabled=0
  2:rig.c(7424):async_data_handler_start returning(0) 
rig.c(254):add_opened_rig returning2(0) 
rig_open: 0x13600ce1c rs->comm_state==1?=1
ft980_open called
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5060 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.1723 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 0b                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.3258 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.2817 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5007 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 0b                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.3508 seconds after 0 chars, direct=1
rig.c(1275) trace
  2:rig.c(2879):rig_get_vfo entered
rig_get_vfo: cache check age=48629ms
rig_get_vfo: cache miss age=48629ms
rig.c(2921) trace
ft980_get_vfo called
ft980_get_status_data called
rig_check_cache_timeout called
rig_check_cache_timeout: forced cache timeout
ft980_transaction called
rig_flush: called for serial device
read_string_generic called, rxmax=4095 direct=1, expected_len=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 01                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.4997 seconds after 0 chars, direct=1
rig_get_vfo: returning -5(read_block_generic called, direct=1
read_block_generic(): Timed out 2.3508 seconds after 0 chars, direct=1
rig.c(1275) trace
  2:rig.c(2879):rig_get_vfo entered
rig_get_vfo: cache check age=48629ms
rig_get_vfo: cache miss age=48629ms
rig.c(2921) trace
ft980_get_vfo called
ft980_get_status_data called
rig_check_cache_timeout called
rig_check_cache_timeout: forced cache timeout
ft980_transaction called
rig_flush: called for serial device
read_string_generic called, rxmax=4095 direct=1, expected_len=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 01                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.4997 seconds after 0 chars, direct=1
Communication timed out
Communication timed out
)
  2:rig_get_vfo: elapsed=2438ms
  2:rig.c(2942):rig_get_vfo returning(-5) Communication timed out

rig_open: vfo_curr=currVFO, tx_vfo=TX
rig_open: default vfo = currVFO
rig_get_freq(1985) called vfo=VFOA
vfo_fixup:(from rig_get_freq:1991) vfo=VFOA, vfo_curr=currVFO, split=0
rig.c(1994) vfo=Main, curr_vfo=currVFO
rig_get_freq: cache miss age=48630ms, cached_vfo=Main, asked_vfo=Main, use_cached_freq=0
rig_get_freq(2081): vfo_opt=0, model=1031
ft980_get_freq: called
  ft980_get_freq: passed vfo = 0x4000000
ft980_get_status_data called
rig_check_cache_timeout called
rig_check_cache_timeout: forced cache timeout
ft980_transaction called
rig_flush: called for serial device
read_string_generic called, rxmax=4095 direct=1, expected_len=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 01                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.3665 seconds after 0 chars, direct=1
 1:rig_get_freq: elapsed=2431ms
 1:rig.c(1370):rig_open returning(0) 
main: rig_open retcode=0
rigctl_parse: called, interactive=1

Rig command: q
 1:rig.c(1392):rig_close entered
ft980_close called
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5002 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.5040 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.4503 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 00                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.4999 seconds after 0 chars, direct=1
write_block(): TX 5 bytes, method=1
0000    00 00 00 00 0b                                      .....           
read_block_generic called, direct=1
read_block_generic(): Timed out 2.4995 seconds after 0 chars, direct=1
  2:rig.c(7461):async_data_handler_stop entered
  2:rig.c(7491):async_data_handler_stop returning(0) 
ser_set_rts: RTS=0
ser_close: restoring options
rig_close(1528): 0x13600ce1c rs->comm_state==0?=0
 1:rig.c(1530):rig_close returning(0) 
ft980_cleanup called