Linux set_powerstat 0 fails to reopen #1212
Comments
mdblack98
added
the
needs test
|
auto_power_on=1 not working on Linux now Howard Nurse hlnurse@cmmsft.com Wed, Jan 11 at 9:38 AM Mike, I believe you made some changes to Icom auto_power_on, and it now appears to be broken. --Howard pi@rigpi3:/var/log $ rigctl -m 3073 -r /dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_IC-7300_02020433-if00-port0 --set-conf=auto_power_on=1 -vvvvv -Z 2023-01-11T10:35:10.289198-0500: rigctl.c(445) Startup: rigctl -m 3073 -r /dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_IC-7300_02020433-if00-port0 --set-conf=auto_power_on=1 -vvvvv -Z 2023-01-11T10:35:10.289412-0500: rigctl Hamlib 4.6~git from indeterminate source revision. 2023-01-11T10:35:10.289460-0500: Report bugs to hamlib-developer@lists.sourceforge.net 2023-01-11T10:35:10.289515-0500: rig_check_rig_caps: p1=0xb6e8fb60, p2=0xb6e952ac, rig_model=0xb6e8fb60, macro_name=0xb6e952ac 2023-01-11T10:35:10.289634-0500: initrigs4_icom: _init called 2023-01-11T10:35:10.289799-0500: rig_init: rig_model=Icom IC-7300 2023-01-11T10:35:10.289930-0500: rig_init: rig has VFO_A 2023-01-11T10:35:10.289976-0500: rig_init: rig has VFO_B 2023-01-11T10:35:10.290016-0500: rig_init: rig has VFO_MEM 2023-01-11T10:35:10.290111-0500: 1:icom.c(623):icom_init entered 2023-01-11T10:35:10.290423-0500: icom_init: done 2023-01-11T10:35:10.290527-0500: 1:icom.c(723):icom_init returning(0) 2023-01-11T10:35:10.290600-0500: rig_token_lookup called for auto_power_on 2023-01-11T10:35:10.290655-0500: rig_confparam_lookup called for auto_power_on 2023-01-11T10:35:10.290713-0500: rig_set_conf called 2023-01-11T10:35:10.290757-0500: rig_confparam_lookup called for 1073741948 2023-01-11T10:35:10.290803-0500: rig_set_conf: auto_power_on='1' 2023-01-11T10:35:10.290918-0500: 1:rig.c(819):rig_open entered 2023-01-11T10:35:10.291019-0500: rig_settings_get_path: path=/home/pi/.config/hamlib_settings 2023-01-11T10:35:10.291179-0500: rig_settings_load_all: settings_file (/home/pi/.config/hamlib_settings): No such file or directory 2023-01-11T10:35:10.291271-0500: rig_open: cwd=/var/log 2023-01-11T10:35:10.291390-0500: rig_open: /var/log/hamlib_settings does not exist 2023-01-11T10:35:10.291452-0500: rig_open: async_data_enable=0, async_data_supported=1 2023-01-11T10:35:10.291514-0500: serial_open: /dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_IC-7300_02020433-if00-port0 2023-01-11T10:35:10.292787-0500: serial_setup: tcgetattr 2023-01-11T10:35:10.292869-0500: serial_setup: cfmakeraw 2023-01-11T10:35:10.292929-0500: serial_setup: cfsetispeed=115200,0x1002 2023-01-11T10:35:10.292982-0500: serial_setup: cfsetospeed=115200,0x1002 2023-01-11T10:35:10.293037-0500: serial_setup: data_bits=8 2023-01-11T10:35:10.293086-0500: serial_setup: parity=0 2023-01-11T10:35:10.293137-0500: serial_setup: Handshake=None 2023-01-11T10:35:10.293198-0500: serial_setup: tcsetattr TCSANOW 2023-01-11T10:35:10.293315-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:10.344659-0500: 2:rig.c(7438):async_data_handler_start entered 2023-01-11T10:35:10.344732-0500: async_data_handler_start: async data support disabled since async_data_enabled=0 2023-01-11T10:35:10.344780-0500: 2:rig.c(7445):async_data_handler_start returning(0) 2023-01-11T10:35:10.344859-0500: rig.c(254):add_opened_rig returning2(0) 2023-01-11T10:35:10.344903-0500: rig_open: 0x105f354 rs->comm_state==1?=1 2023-01-11T10:35:10.344991-0500: 2:icom.c(986):icom_rig_open entered 2023-01-11T10:35:10.345034-0500: icom_rig_open: IC-7300 v20230109.10 2023-01-11T10:35:10.345086-0500: 3:icom.c(776):icom_get_usb_echo_off entered 2023-01-11T10:35:10.345357-0500: 4:frame.c(425):icom_transaction entered 2023-01-11T10:35:10.345410-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-11T10:35:10.345457-0500: 5:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:10.345503-0500: rig_flush: called for serial device 2023-01-11T10:35:10.346234-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:10.347426-0500: write_block(): TX 6 bytes, method=2 2023-01-11T10:35:10.347517-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:10.347570-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:11.348697-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-11T10:35:11.348833-0500: 5:frame.c(294):icom_one_transaction returning(-5) Communication timed out 2023-01-11T10:35:11.348955-0500: icom_transaction: retry=0: async_data_handler_start: async data support disabled since async_data_enabled=0 2:rig.c(7445):async_data_handler_start returning(0) rig.c(254):add_opened_rig returning2(0) rig_open: 0x105f354 rs->comm_state==1?=1 2:icom.c(986):icom_rig_open entered icom_rig_open: IC-7300 v20230109.10 3:icom.c(776):icom_get_usb_echo_off entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out 2023-01-11T10:35:11.449507-0500: icom_transaction: failed: rig.c(254):add_opened_rig returning2(0) rig_open: 0x105f354 rs->comm_state==1?=1 2:icom.c(986):icom_rig_open entered icom_rig_open: IC-7300 v20230109.10 3:icom.c(776):icom_get_usb_echo_off entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out Communication timed out 2023-01-11T10:35:11.449734-0500: 4:frame.c(455):icom_transaction returning(-5) Communication timed out 2023-01-11T10:35:11.449827-0500: 3:icom.c(784):icom_get_usb_echo_off returning(-5) Communication timed out 2023-01-11T10:35:11.449879-0500: icom_rig_open: echo status result=-5 2023-01-11T10:35:11.449922-0500: icom_rig_open: echo status unknown 2023-01-11T10:35:11.449964-0500: icom_rig_open trying power on 2023-01-11T10:35:11.450060-0500: rig_set_powerstat called status=1 2023-01-11T10:35:11.450104-0500: rig.c(6019) trace 2023-01-11T10:35:11.450146-0500: icom_set_powerstat called status=1 2023-01-11T10:35:12.450342-0500: write_block(): TX 175 bytes, method=2 2023-01-11T10:35:12.450459-0500: 0000 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:12.450511-0500: 0010 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:12.450561-0500: 0020 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:12.450609-0500: 0030 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:12.450658-0500: 0040 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:12.450707-0500: 0050 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:12.450755-0500: 0060 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:12.450838-0500: 0070 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:12.450888-0500: 0080 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:12.450938-0500: 0090 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:12.450988-0500: 00a0 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ............... 2023-01-11T10:35:12.451043-0500: 3:rig.c(1399):rig_close entered 2023-01-11T10:35:12.451092-0500: 4:icom.c(1128):icom_rig_close entered 2023-01-11T10:35:12.451141-0500: 4:icom.c(1150):icom_rig_close returning(0) 2023-01-11T10:35:12.451189-0500: 4:rig.c(7482):async_data_handler_stop entered 2023-01-11T10:35:12.451244-0500: 4:rig.c(7512):async_data_handler_stop returning(0) 2023-01-11T10:35:12.451338-0500: ser_close: restoring options 2023-01-11T10:35:12.451462-0500: rig_close(1535): 0x105f354 rs->comm_state==0?=0 2023-01-11T10:35:12.451513-0500: 3:rig.c(1537):rig_close returning(0) 2023-01-11T10:35:13.451675-0500: 3:rig.c(819):rig_open entered 2023-01-11T10:35:13.451787-0500: rig_settings_get_path: path=/home/pi/.config/hamlib_settings 2023-01-11T10:35:13.451871-0500: rig_settings_load_all: settings_file (/home/pi/.config/hamlib_settings): No such file or directory 2023-01-11T10:35:13.451928-0500: rig_open: cwd=/var/log 2023-01-11T10:35:13.451996-0500: rig_open: /var/log/hamlib_settings does not exist 2023-01-11T10:35:13.452045-0500: rig_open: async_data_enable=0, async_data_supported=1 2023-01-11T10:35:13.452095-0500: serial_open: /dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_IC-7300_02020433-if00-port0 2023-01-11T10:35:13.453937-0500: serial_setup: tcgetattr 2023-01-11T10:35:13.454002-0500: serial_setup: cfmakeraw 2023-01-11T10:35:13.454048-0500: serial_setup: cfsetispeed=115200,0x1002 2023-01-11T10:35:13.454093-0500: serial_setup: cfsetospeed=115200,0x1002 2023-01-11T10:35:13.454136-0500: serial_setup: data_bits=8 2023-01-11T10:35:13.454177-0500: serial_setup: parity=0 2023-01-11T10:35:13.454220-0500: serial_setup: Handshake=None 2023-01-11T10:35:13.454267-0500: serial_setup: tcsetattr TCSANOW 2023-01-11T10:35:13.454326-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:13.505603-0500: 4:rig.c(7438):async_data_handler_start entered 2023-01-11T10:35:13.505690-0500: async_data_handler_start: async data support disabled since async_data_enabled=0 2023-01-11T10:35:13.505744-0500: 4:rig.c(7445):async_data_handler_start returning(0) 2023-01-11T10:35:13.505801-0500: rig.c(254):add_opened_rig returning2(0) 2023-01-11T10:35:13.505852-0500: rig_open: 0x105f354 rs->comm_state==1?=1 2023-01-11T10:35:13.505906-0500: 4:icom.c(986):icom_rig_open entered 2023-01-11T10:35:13.505957-0500: icom_rig_open: IC-7300 v20230109.10 2023-01-11T10:35:13.506009-0500: 5:icom.c(776):icom_get_usb_echo_off entered 2023-01-11T10:35:13.506060-0500: 6:frame.c(425):icom_transaction entered 2023-01-11T10:35:13.506111-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-11T10:35:13.506162-0500: 7:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:13.506215-0500: rig_flush: called for serial device 2023-01-11T10:35:13.506266-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:13.507464-0500: write_block(): TX 6 bytes, method=2 2023-01-11T10:35:13.507610-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:13.507663-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:13.509166-0500: read_string_generic(): RX 6 characters, direct=1 2023-01-11T10:35:13.509232-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:13.509288-0500: icom_one_transaction: frm_len=6, frm_len-1=fd, frm_len-2=03 2023-01-11T10:35:13.509394-0500: 7:frame.c(403):icom_one_transaction returning(0) 2023-01-11T10:35:13.509450-0500: 6:frame.c(455):icom_transaction returning(0) 2023-01-11T10:35:13.509502-0500: icom_get_usb_echo_off: ack_len=1 2023-01-11T10:35:13.509591-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:13.509788-0500: read_string_generic(): RX 6 characters, direct=1 2023-01-11T10:35:13.509843-0500: 0000 fe fe e0 94 fa fd ...... 2023-01-11T10:35:13.509892-0500: icom_get_usb_echo_off: USB echo on detected, get freq retval=6 2023-01-11T10:35:13.509943-0500: 5:icom.c(805):icom_get_usb_echo_off returning(0) 2023-01-11T10:35:13.509994-0500: icom_rig_open: echo status result=0 2023-01-11T10:35:13.510043-0500: icom_rig_open: echo status known, getting frequency 2023-01-11T10:35:13.510111-0500: rig_get_freq(1992) called vfo=currVFO 2023-01-11T10:35:13.510223-0500: vfo_fixup:(from rig_get_freq:1998) vfo=currVFO, vfo_curr=None, split=0 2023-01-11T10:35:13.510276-0500: vfo_fixup: Leaving currVFO alone 2023-01-11T10:35:13.510326-0500: rig.c(2001) vfo=currVFO, curr_vfo=None 2023-01-11T10:35:13.510552-0500: rig_get_freq: cache miss age=1000000ms, cached_vfo=None, asked_vfo=None, use_cached_freq=0 2023-01-11T10:35:13.510614-0500: rig_get_freq(2088): vfo_opt=0, model=3073 2023-01-11T10:35:13.510706-0500: icom_get_freq called for None, curr_vfo=None 2023-01-11T10:35:13.510762-0500: icom_get_freq: using vfo=None 2023-01-11T10:35:13.510817-0500: 5:frame.c(425):icom_transaction entered 2023-01-11T10:35:13.510893-0500: icom_transaction: cmd=0x25, subcmd=0x00, payload_len=0 2023-01-11T10:35:13.510949-0500: 6:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:13.511024-0500: rig_flush: called for serial device 2023-01-11T10:35:13.511098-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:13.512284-0500: write_block(): TX 7 bytes, method=2 2023-01-11T10:35:13.512347-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-11T10:35:13.512401-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:14.513544-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-11T10:35:14.513639-0500: 6:frame.c(185):icom_one_transaction returning(-13) Communication bus error 2023-01-11T10:35:14.513798-0500: icom_transaction: retry=0: rig_get_cache(435): vfo=VFOA, freq=0, mode=, width=0 rig_get_freq(2058): freqMainA=0, modeMainA=, widthMainA=0 rig_get_freq(2058): freqMainB=0, modeMainB=, widthMainB=0 rig_get_freq: cache miss age=1000000ms, cached_vfo=None, asked_vfo=None, use_cached_freq=0 rig_get_freq(2088): vfo_opt=0, model=3073 icom_get_freq called for None, curr_vfo=None icom_get_freq: using vfo=None icom_transaction: cmd=0x25, subcmd=0x00, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 25 00 fd ....%.. read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication bus error Communication bus error 2023-01-11T10:35:14.614347-0500: icom_transaction: failed: rig_get_freq(2058): freqMainB=0, modeMainB=, widthMainB=0 rig_get_freq: cache miss age=1000000ms, cached_vfo=None, asked_vfo=None, use_cached_freq=0 rig_get_freq(2088): vfo_opt=0, model=3073 icom_get_freq called for None, curr_vfo=None icom_get_freq: using vfo=None icom_transaction: cmd=0x25, subcmd=0x00, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 25 00 fd ....%.. read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:14.614646-0500: 5:frame.c(455):icom_transaction returning(-13) Communication bus error 2023-01-11T10:35:14.614851-0500: icom_get_freq: rig probe shows 0x25 CI-V cmd not available 2023-01-11T10:35:14.614923-0500: icom.c(1656) trace 2023-01-11T10:35:14.614975-0500: set_vfo_curr: vfo=None, curr_vfo=None 2023-01-11T10:35:14.615030-0500: set_vfo_curr: curr_vfo now=None 2023-01-11T10:35:14.615080-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:14.615158-0500: 5:frame.c(425):icom_transaction entered 2023-01-11T10:35:14.615224-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-11T10:35:14.615276-0500: 6:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:14.615377-0500: rig_flush: called for serial device 2023-01-11T10:35:14.615436-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:14.616777-0500: write_block(): TX 6 bytes, method=2 2023-01-11T10:35:14.616862-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:14.616919-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:15.618061-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-11T10:35:15.618152-0500: 6:frame.c(185):icom_one_transaction returning(-13) Communication bus error 2023-01-11T10:35:15.618274-0500: icom_transaction: retry=0: 5:frame.c(455):icom_transaction returning(-13) Communication bus error icom_get_freq: rig probe shows 0x25 CI-V cmd not available icom.c(1656) trace set_vfo_curr: vfo=None, curr_vfo=None set_vfo_curr: curr_vfo now=None icom.c(9429):set_vfo_curr returning2(0) icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication bus error Communication bus error 2023-01-11T10:35:15.718724-0500: icom_transaction: failed: icom_get_freq: rig probe shows 0x25 CI-V cmd not available icom.c(1656) trace set_vfo_curr: vfo=None, curr_vfo=None set_vfo_curr: curr_vfo now=None icom.c(9429):set_vfo_curr returning2(0) icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:15.719058-0500: 5:frame.c(455):icom_transaction returning(-13) Communication bus error 2023-01-11T10:35:15.719190-0500: icom.c(1667) trace 2023-01-11T10:35:15.719271-0500: set_vfo_curr: vfo=None, curr_vfo=None 2023-01-11T10:35:15.719345-0500: set_vfo_curr: curr_vfo now=None 2023-01-11T10:35:15.719419-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:15.719478-0500: 4:icom.c(1685):icom_get_freq returning(-13) Communication bus error 2023-01-11T10:35:15.719733-0500: 3:rig_get_freq: elapsed=2210ms 2023-01-11T10:35:15.719794-0500: rig_get_freq(1992) called vfo=otherVFO 2023-01-11T10:35:15.719930-0500: vfo_fixup:(from rig_get_freq:1998) vfo=otherVFO, vfo_curr=None, split=0 2023-01-11T10:35:15.720007-0500: rig.c(2001) vfo=otherVFO, curr_vfo=None 2023-01-11T10:35:15.720138-0500: rig_get_cache(303): unknown vfo=otherVFO 2023-01-11T10:35:15.720278-0500: rig_get_freq: cache miss age=1000000ms, cached_vfo=otherVFO, asked_vfo=otherVFO, use_cached_freq=0 2023-01-11T10:35:15.720336-0500: rig_get_freq(2088): vfo_opt=0, model=3073 2023-01-11T10:35:15.720391-0500: icom_get_freq called for otherVFO, curr_vfo=None 2023-01-11T10:35:15.720444-0500: icom_get_freq: using vfo=otherVFO 2023-01-11T10:35:15.720497-0500: icom.c(1656) trace 2023-01-11T10:35:15.720550-0500: set_vfo_curr: vfo=otherVFO, curr_vfo=None 2023-01-11T10:35:15.720604-0500: set_vfo_curr: setting new vfo=otherVFO 2023-01-11T10:35:15.720656-0500: icom.c(9414) trace 2023-01-11T10:35:15.720715-0500: 4:rig.c(2729):rig_set_vfo entered 2023-01-11T10:35:15.720769-0500: rig_set_vfo called vfo=otherVFO 2023-01-11T10:35:15.720862-0500: vfo_fixup:(from rig_set_vfo:2749) vfo=otherVFO, vfo_curr=None, split=0 2023-01-11T10:35:15.720920-0500: vfo_fixup:(from rig_set_vfo:2791) vfo=otherVFO, vfo_curr=None, split=0 2023-01-11T10:35:15.720973-0500: rig.c(2810) trace 2023-01-11T10:35:15.721025-0500: icom_set_vfo called vfo=otherVFO 2023-01-11T10:35:15.721079-0500: icom_set_vfo: line#2863 2023-01-11T10:35:15.721130-0500: icom_set_vfo: unknown vfo 'otherVFO' 2023-01-11T10:35:15.721185-0500: icom.c(3063):icom_set_vfo returning2(-1) Invalid parameter 2023-01-11T10:35:15.721287-0500: rig_set_vfo: set_vfo otherVFO failed with 'rig_get_freq: cache miss age=1000000ms, cached_vfo=otherVFO, asked_vfo=otherVFO, use_cached_freq=0 rig_get_freq(2088): vfo_opt=0, model=3073 icom_get_freq called for otherVFO, curr_vfo=None icom_get_freq: using vfo=otherVFO icom.c(1656) trace set_vfo_curr: vfo=otherVFO, curr_vfo=None set_vfo_curr: setting new vfo=otherVFO icom.c(9414) trace rig_set_vfo called vfo=otherVFO vfo_fixup:(from rig_set_vfo:2749) vfo=otherVFO, vfo_curr=None, split=0 vfo_fixup:(from rig_set_vfo:2791) vfo=otherVFO, vfo_curr=None, split=0 rig.c(2810) trace icom_set_vfo called vfo=otherVFO icom_set_vfo: line#2863 icom_set_vfo: unknown vfo 'otherVFO' icom.c(3063):icom_set_vfo returning2(-1) Invalid parameter Invalid parameter Invalid parameter ' 2023-01-11T10:35:15.721664-0500: 5:rig.c(2886):rig_get_vfo entered 2023-01-11T10:35:15.721762-0500: rig_get_vfo: no get_vfo 2023-01-11T10:35:15.721855-0500: 5:rig_get_vfo: elapsed=0ms 2023-01-11T10:35:15.721916-0500: 5:rig.c(2909):rig_get_vfo returning(-11) Feature not available 2023-01-11T10:35:15.721973-0500: rig_set_vfo: Expiring all cache due to VFO change and no get_vfo 2023-01-11T10:35:15.722060-0500: rig_set_vfo: return -1, vfo=otherVFO, curr_vfo=None 2023-01-11T10:35:15.722117-0500: 4:rig_set_vfo: elapsed=1ms 2023-01-11T10:35:15.722173-0500: 4:rig.c(2861):rig_set_vfo returning(-1) Invalid parameter 2023-01-11T10:35:15.722233-0500: icom.c(9419):set_vfo_curr returning2(-1) Invalid parameter 2023-01-11T10:35:15.722293-0500: 3:icom.c(1663):icom_get_freq returning(-1) Invalid parameter 2023-01-11T10:35:15.722407-0500: rig_get_cache(303): unknown vfo=otherVFO 2023-01-11T10:35:15.722500-0500: rig_set_cache_freq(209): unknown vfo?, vfo=otherVFO 2023-01-11T10:35:15.722559-0500: 2:rig_get_freq: elapsed=3ms 2023-01-11T10:35:15.722623-0500: rig_set_freq called vfo=currVFO, freq=100 2023-01-11T10:35:15.722680-0500: vfo_fixup:(from rig_set_freq:1781) vfo=currVFO, vfo_curr=None, split=0 2023-01-11T10:35:15.722733-0500: vfo_fixup: Leaving currVFO alone 2023-01-11T10:35:15.722783-0500: rig_set_freq: TARGETABLE_FREQ vfo=currVFO 2023-01-11T10:35:15.722871-0500: rig.c(1809) trace 2023-01-11T10:35:15.722928-0500: icom_set_freq called currVFO=100 2023-01-11T10:35:15.722984-0500: rig_get_freq(1992) called vfo=currVFO 2023-01-11T10:35:15.723075-0500: vfo_fixup:(from rig_get_freq:1998) vfo=currVFO, vfo_curr=None, split=0 2023-01-11T10:35:15.723128-0500: vfo_fixup: Leaving currVFO alone 2023-01-11T10:35:15.723179-0500: rig.c(2001) vfo=currVFO, curr_vfo=None 2023-01-11T10:35:15.723350-0500: rig_get_freq: cache miss age=10001ms, cached_vfo=None, asked_vfo=None, use_cached_freq=0 2023-01-11T10:35:15.723404-0500: rig_get_freq(2088): vfo_opt=0, model=3073 2023-01-11T10:35:15.723457-0500: icom_get_freq called for None, curr_vfo=None 2023-01-11T10:35:15.723509-0500: icom_get_freq: using vfo=None 2023-01-11T10:35:15.723561-0500: icom.c(1656) trace 2023-01-11T10:35:15.723612-0500: set_vfo_curr: vfo=None, curr_vfo=None 2023-01-11T10:35:15.723664-0500: set_vfo_curr: curr_vfo now=None 2023-01-11T10:35:15.723715-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:15.723770-0500: 3:frame.c(425):icom_transaction entered 2023-01-11T10:35:15.723861-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-11T10:35:15.723917-0500: 4:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:15.723971-0500: rig_flush: called for serial device 2023-01-11T10:35:15.724025-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:15.725213-0500: write_block(): TX 6 bytes, method=2 2023-01-11T10:35:15.725386-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:15.725443-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:16.726583-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-11T10:35:16.726679-0500: 4:frame.c(185):icom_one_transaction returning(-13) Communication bus error 2023-01-11T10:35:16.726795-0500: icom_transaction: retry=0: rig_get_freq(2088): vfo_opt=0, model=3073 icom_get_freq called for None, curr_vfo=None icom_get_freq: using vfo=None icom.c(1656) trace set_vfo_curr: vfo=None, curr_vfo=None set_vfo_curr: curr_vfo now=None icom.c(9429):set_vfo_curr returning2(0) 3:frame.c(425):icom_transaction entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication bus error Communication bus error 2023-01-11T10:35:16.827413-0500: icom_transaction: failed: icom_get_freq: using vfo=None icom.c(1656) trace set_vfo_curr: vfo=None, curr_vfo=None set_vfo_curr: curr_vfo now=None icom.c(9429):set_vfo_curr returning2(0) 3:frame.c(425):icom_transaction entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:16.827720-0500: 3:frame.c(455):icom_transaction returning(-13) Communication bus error 2023-01-11T10:35:16.827851-0500: icom.c(1667) trace 2023-01-11T10:35:16.827928-0500: set_vfo_curr: vfo=None, curr_vfo=None 2023-01-11T10:35:16.828043-0500: set_vfo_curr: curr_vfo now=None 2023-01-11T10:35:16.828118-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:16.828178-0500: 2:icom.c(1685):icom_get_freq returning(-13) Communication bus error 2023-01-11T10:35:16.828400-0500: 1:rig_get_freq: elapsed=1105ms 2023-01-11T10:35:16.828462-0500: icom.c(1324):icom_set_freq returning2(-13) Communication bus error 2023-01-11T10:35:16.828524-0500: 1:rig.c(1816):rig_set_freq returning(-13) Communication bus error 2023-01-11T10:35:16.828588-0500: 1:rig.c(2729):rig_set_vfo entered 2023-01-11T10:35:16.828640-0500: rig_set_vfo called vfo=VFOA 2023-01-11T10:35:16.828694-0500: vfo_fixup:(from rig_set_vfo:2749) vfo=VFOA, vfo_curr=None, split=0 2023-01-11T10:35:16.828750-0500: vfo_fixup:(from rig_set_vfo:2791) vfo=VFOA, vfo_curr=None, split=0 2023-01-11T10:35:16.828802-0500: rig.c(2810) trace 2023-01-11T10:35:16.828854-0500: icom_set_vfo called vfo=VFOA 2023-01-11T10:35:16.828905-0500: icom_set_vfo: line#2863 2023-01-11T10:35:16.828955-0500: icom_set_vfo: line#3066 2023-01-11T10:35:16.829048-0500: 2:frame.c(425):icom_transaction entered 2023-01-11T10:35:16.829102-0500: icom_transaction: cmd=0x07, subcmd=0x00, payload_len=0 2023-01-11T10:35:16.829156-0500: 3:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:16.829210-0500: rig_flush: called for serial device 2023-01-11T10:35:16.829263-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:16.830451-0500: write_block(): TX 7 bytes, method=2 2023-01-11T10:35:16.830551-0500: 0000 fe fe 94 e0 07 00 fd ....... 2023-01-11T10:35:16.830604-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:17.831738-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-11T10:35:17.831832-0500: 3:frame.c(185):icom_one_transaction returning(-13) Communication bus error 2023-01-11T10:35:17.831944-0500: icom_transaction: retry=0: rig_set_vfo called vfo=VFOA vfo_fixup:(from rig_set_vfo:2749) vfo=VFOA, vfo_curr=None, split=0 vfo_fixup:(from rig_set_vfo:2791) vfo=VFOA, vfo_curr=None, split=0 rig.c(2810) trace icom_set_vfo called vfo=VFOA icom_set_vfo: line#2863 icom_set_vfo: line#3066 2:frame.c(425):icom_transaction entered icom_transaction: cmd=0x07, subcmd=0x00, payload_len=0 3:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 07 00 fd ....... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 3:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:17.932552-0500: icom_transaction: failed: vfo_fixup:(from rig_set_vfo:2791) vfo=VFOA, vfo_curr=None, split=0 rig.c(2810) trace icom_set_vfo called vfo=VFOA icom_set_vfo: line#2863 icom_set_vfo: line#3066 2:frame.c(425):icom_transaction entered icom_transaction: cmd=0x07, subcmd=0x00, payload_len=0 3:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 07 00 fd ....... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 3:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:17.932854-0500: 2:frame.c(455):icom_transaction returning(-13) Communication bus error 2023-01-11T10:35:17.932982-0500: icom_set_vfo: line#3069 2023-01-11T10:35:17.933041-0500: icom.c(3073):icom_set_vfo returning2(-13) Communication bus error 2023-01-11T10:35:17.933228-0500: rig_set_vfo: set_vfo VFOA failed with ' 3:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 07 00 fd ....... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 3:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error 2:frame.c(455):icom_transaction returning(-13) Communication bus error icom_set_vfo: line#3069 icom.c(3073):icom_set_vfo returning2(-13) Communication bus error Communication bus error Communication bus error ' 2023-01-11T10:35:17.933642-0500: 2:rig.c(2886):rig_get_vfo entered 2023-01-11T10:35:17.933699-0500: rig_get_vfo: no get_vfo 2023-01-11T10:35:17.933762-0500: 2:rig_get_vfo: elapsed=0ms 2023-01-11T10:35:17.933844-0500: 2:rig.c(2909):rig_get_vfo returning(-11) Feature not available 2023-01-11T10:35:17.933919-0500: rig_set_vfo: Expiring all cache due to VFO change and no get_vfo 2023-01-11T10:35:17.934025-0500: rig_set_vfo: return -13, vfo=VFOA, curr_vfo=None 2023-01-11T10:35:17.934107-0500: 1:rig_set_vfo: elapsed=1106ms 2023-01-11T10:35:17.934224-0500: 1:rig.c(2861):rig_set_vfo returning(-13) Communication bus error 2023-01-11T10:35:17.934376-0500: rig_get_freq(1992) called vfo=currVFO 2023-01-11T10:35:17.934532-0500: vfo_fixup:(from rig_get_freq:1998) vfo=currVFO, vfo_curr=None, split=0 2023-01-11T10:35:17.934640-0500: vfo_fixup: Leaving currVFO alone 2023-01-11T10:35:17.934742-0500: rig.c(2001) vfo=currVFO, curr_vfo=None 2023-01-11T10:35:17.934972-0500: rig_get_freq: cache miss age=10000ms, cached_vfo=None, asked_vfo=None, use_cached_freq=0 2023-01-11T10:35:17.935524-0500: rig_get_freq(2088): vfo_opt=0, model=3073 2023-01-11T10:35:17.935893-0500: icom_get_freq called for None, curr_vfo=None 2023-01-11T10:35:17.936295-0500: icom_get_freq: using vfo=None 2023-01-11T10:35:17.936635-0500: icom.c(1656) trace 2023-01-11T10:35:17.936969-0500: set_vfo_curr: vfo=None, curr_vfo=None 2023-01-11T10:35:17.937420-0500: set_vfo_curr: curr_vfo now=None 2023-01-11T10:35:17.937761-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:17.938102-0500: 1:frame.c(425):icom_transaction entered 2023-01-11T10:35:17.938487-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-11T10:35:17.938831-0500: 2:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:17.939209-0500: rig_flush: called for serial device 2023-01-11T10:35:17.939553-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:17.941028-0500: write_block(): TX 6 bytes, method=2 2023-01-11T10:35:17.941856-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:17.942404-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:18.943942-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-11T10:35:18.944592-0500: 2:frame.c(185):icom_one_transaction returning(-13) Communication bus error 2023-01-11T10:35:18.945373-0500: icom_transaction: retry=0: rig_get_freq(2088): vfo_opt=0, model=3073 icom_get_freq called for None, curr_vfo=None icom_get_freq: using vfo=None icom.c(1656) trace set_vfo_curr: vfo=None, curr_vfo=None set_vfo_curr: curr_vfo now=None icom.c(9429):set_vfo_curr returning2(0) 1:frame.c(425):icom_transaction entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:19.050395-0500: icom_transaction: failed: icom_get_freq: using vfo=None icom.c(1656) trace set_vfo_curr: vfo=None, curr_vfo=None set_vfo_curr: curr_vfo now=None icom.c(9429):set_vfo_curr returning2(0) 1:frame.c(425):icom_transaction entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:19.052084-0500: 1:frame.c(455):icom_transaction returning(-13) Communication bus error 2023-01-11T10:35:19.052479-0500: icom.c(1667) trace 2023-01-11T10:35:19.052587-0500: set_vfo_curr: vfo=None, curr_vfo=None 2023-01-11T10:35:19.052822-0500: set_vfo_curr: curr_vfo now=None 2023-01-11T10:35:19.052928-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:19.053171-0500: 0:icom.c(1685):icom_get_freq returning(-13) Communication bus error 2023-01-11T10:35:19.053464-0500: -1:rig_get_freq: elapsed=1119ms 2023-01-11T10:35:19.053824-0500: 0:rig.c(2729):rig_set_vfo entered 2023-01-11T10:35:19.054061-0500: rig_set_vfo called vfo=VFOB 2023-01-11T10:35:19.054323-0500: rig_set_vfo ********************** called vfo=VFOB 2023-01-11T10:35:19.054573-0500: vfo_fixup:(from rig_set_vfo:2749) vfo=VFOB, vfo_curr=None, split=0 2023-01-11T10:35:19.054679-0500: vfo_fixup: final vfo=VFOB 2023-01-11T10:35:19.054918-0500: vfo_fixup:(from rig_set_vfo:2791) vfo=VFOB, vfo_curr=None, split=0 2023-01-11T10:35:19.055023-0500: vfo_fixup: final vfo=VFOB 2023-01-11T10:35:19.055258-0500: rig.c(2810) trace 2023-01-11T10:35:19.055737-0500: icom_set_vfo called vfo=VFOB 2023-01-11T10:35:19.055844-0500: icom_set_vfo: line#2863 2023-01-11T10:35:19.056084-0500: icom_set_vfo: line#3066 2023-01-11T10:35:19.056192-0500: 1:frame.c(425):icom_transaction entered 2023-01-11T10:35:19.056474-0500: icom_transaction: cmd=0x07, subcmd=0x01, payload_len=0 2023-01-11T10:35:19.056580-0500: 2:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:19.056821-0500: rig_flush: called for serial device 2023-01-11T10:35:19.056927-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:19.058394-0500: write_block(): TX 7 bytes, method=2 2023-01-11T10:35:19.058699-0500: 0000 fe fe 94 e0 07 01 fd ....... 2023-01-11T10:35:19.058933-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:20.060122-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-11T10:35:20.060605-0500: 2:frame.c(185):icom_one_transaction returning(-13) Communication bus error 2023-01-11T10:35:20.060792-0500: icom_transaction: retry=0: vfo_fixup: final vfo=VFOB vfo_fixup:(from rig_set_vfo:2791) vfo=VFOB, vfo_curr=None, split=0 vfo_fixup: final vfo=VFOB rig.c(2810) trace icom_set_vfo called vfo=VFOB icom_set_vfo: line#2863 icom_set_vfo: line#3066 1:frame.c(425):icom_transaction entered icom_transaction: cmd=0x07, subcmd=0x01, payload_len=0 2:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 07 01 fd ....... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:20.162710-0500: icom_transaction: failed: vfo_fixup: final vfo=VFOB rig.c(2810) trace icom_set_vfo called vfo=VFOB icom_set_vfo: line#2863 icom_set_vfo: line#3066 1:frame.c(425):icom_transaction entered icom_transaction: cmd=0x07, subcmd=0x01, payload_len=0 2:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 07 01 fd ....... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:20.164474-0500: 1:frame.c(455):icom_transaction returning(-13) Communication bus error 2023-01-11T10:35:20.164661-0500: icom_set_vfo: line#3069 2023-01-11T10:35:20.165002-0500: icom.c(3073):icom_set_vfo returning2(-13) Communication bus error 2023-01-11T10:35:20.165191-0500: rig_set_vfo: set_vfo VFOB failed with ' 2:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 07 01 fd ....... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error 1:frame.c(455):icom_transaction returning(-13) Communication bus error icom_set_vfo: line#3069 icom.c(3073):icom_set_vfo returning2(-13) Communication bus error Communication bus error Communication bus error ' 2023-01-11T10:35:20.166946-0500: 1:rig.c(2886):rig_get_vfo entered 2023-01-11T10:35:20.167055-0500: rig_get_vfo: no get_vfo 2023-01-11T10:35:20.167170-0500: 1:rig_get_vfo: elapsed=0ms 2023-01-11T10:35:20.167582-0500: 1:rig.c(2909):rig_get_vfo returning(-11) Feature not available 2023-01-11T10:35:20.167717-0500: rig_set_vfo: Expiring all cache due to VFO change and no get_vfo 2023-01-11T10:35:20.167861-0500: rig_set_vfo: return -13, vfo=VFOB, curr_vfo=None 2023-01-11T10:35:20.168138-0500: 0:rig_set_vfo: elapsed=1114ms 2023-01-11T10:35:20.168250-0500: 0:rig.c(2861):rig_set_vfo returning(-13) Communication bus error 2023-01-11T10:35:20.168562-0500: rig_set_freq called vfo=currVFO, freq=0 2023-01-11T10:35:20.168802-0500: vfo_fixup:(from rig_set_freq:1781) vfo=currVFO, vfo_curr=None, split=0 2023-01-11T10:35:20.168908-0500: vfo_fixup: Leaving currVFO alone 2023-01-11T10:35:20.169146-0500: rig_set_freq: TARGETABLE_FREQ vfo=currVFO 2023-01-11T10:35:20.169247-0500: rig.c(1809) trace 2023-01-11T10:35:20.169520-0500: icom_set_freq called currVFO=0 2023-01-11T10:35:20.169628-0500: rig_get_freq(1992) called vfo=currVFO 2023-01-11T10:35:20.169909-0500: vfo_fixup:(from rig_get_freq:1998) vfo=currVFO, vfo_curr=None, split=0 2023-01-11T10:35:20.170143-0500: vfo_fixup: Leaving currVFO alone 2023-01-11T10:35:20.170366-0500: rig.c(2001) vfo=currVFO, curr_vfo=None 2023-01-11T10:35:20.170645-0500: rig_get_freq: cache miss age=10002ms, cached_vfo=None, asked_vfo=None, use_cached_freq=0 2023-01-11T10:35:20.171000-0500: rig_get_freq(2088): vfo_opt=0, model=3073 2023-01-11T10:35:20.171232-0500: icom_get_freq called for None, curr_vfo=None 2023-01-11T10:35:20.171343-0500: icom_get_freq: using vfo=None 2023-01-11T10:35:20.171620-0500: icom.c(1656) trace 2023-01-11T10:35:20.171723-0500: set_vfo_curr: vfo=None, curr_vfo=None 2023-01-11T10:35:20.171826-0500: set_vfo_curr: curr_vfo now=None 2023-01-11T10:35:20.172065-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:20.172172-0500: 0:frame.c(425):icom_transaction entered 2023-01-11T10:35:20.172492-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-11T10:35:20.172725-0500: 1:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:20.172836-0500: rig_flush: called for serial device 2023-01-11T10:35:20.173075-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:20.174318-0500: write_block(): TX 6 bytes, method=2 2023-01-11T10:35:20.174596-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:20.174700-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:21.176046-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-11T10:35:21.176144-0500: 1:frame.c(185):icom_one_transaction returning(-13) Communication bus error 2023-01-11T10:35:21.176251-0500: icom_transaction: retry=0: rig_get_freq(2088): vfo_opt=0, model=3073 icom_get_freq called for None, curr_vfo=None icom_get_freq: using vfo=None icom.c(1656) trace set_vfo_curr: vfo=None, curr_vfo=None set_vfo_curr: curr_vfo now=None icom.c(9429):set_vfo_curr returning2(0) 0:frame.c(425):icom_transaction entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 1:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 1:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:21.276721-0500: icom_transaction: failed: icom_get_freq: using vfo=None icom.c(1656) trace set_vfo_curr: vfo=None, curr_vfo=None set_vfo_curr: curr_vfo now=None icom.c(9429):set_vfo_curr returning2(0) 0:frame.c(425):icom_transaction entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 1:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 1:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:21.276982-0500: 0:frame.c(455):icom_transaction returning(-13) Communication bus error 2023-01-11T10:35:21.277080-0500: icom.c(1667) trace 2023-01-11T10:35:21.277133-0500: set_vfo_curr: vfo=None, curr_vfo=None 2023-01-11T10:35:21.277183-0500: set_vfo_curr: curr_vfo now=None 2023-01-11T10:35:21.277232-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:21.277287-0500: -1:icom.c(1685):icom_get_freq returning(-13) Communication bus error 2023-01-11T10:35:21.277528-0500: -2:rig_get_freq: elapsed=1108ms 2023-01-11T10:35:21.277629-0500: icom.c(1324):icom_set_freq returning2(-13) Communication bus error 2023-01-11T10:35:21.277691-0500: -2:rig.c(1816):rig_set_freq returning(-13) Communication bus error 2023-01-11T10:35:21.277752-0500: icom_current_vfo_x25: currVFO=VFOB 2023-01-11T10:35:21.277805-0500: rig_get_freq(1992) called vfo=currVFO 2023-01-11T10:35:21.277899-0500: vfo_fixup:(from rig_get_freq:1998) vfo=currVFO, vfo_curr=VFOB, split=0 2023-01-11T10:35:21.277950-0500: vfo_fixup: Leaving currVFO alone 2023-01-11T10:35:21.277999-0500: rig.c(2001) vfo=currVFO, curr_vfo=VFOB 2023-01-11T10:35:21.278179-0500: rig_get_freq: cache miss age=11110ms, cached_vfo=VFOB, asked_vfo=VFOB, use_cached_freq=0 2023-01-11T10:35:21.278276-0500: rig_get_freq(2088): vfo_opt=0, model=3073 2023-01-11T10:35:21.278330-0500: icom_get_freq called for VFOB, curr_vfo=VFOB 2023-01-11T10:35:21.278384-0500: icom_get_freq: using vfo=VFOB 2023-01-11T10:35:21.278454-0500: icom.c(1656) trace 2023-01-11T10:35:21.278503-0500: set_vfo_curr: vfo=VFOB, curr_vfo=VFOB 2023-01-11T10:35:21.278556-0500: set_vfo_curr: curr_vfo now=VFOB 2023-01-11T10:35:21.278665-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:21.278723-0500: -2:frame.c(425):icom_transaction entered 2023-01-11T10:35:21.278795-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-11T10:35:21.278851-0500: -1:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:21.278908-0500: rig_flush: called for serial device 2023-01-11T10:35:21.278981-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:21.280173-0500: write_block(): TX 6 bytes, method=2 2023-01-11T10:35:21.280278-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:21.280333-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:22.281470-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-11T10:35:22.281567-0500: -1:frame.c(185):icom_one_transaction returning(-13) Communication bus error 2023-01-11T10:35:22.281689-0500: icom_transaction: retry=0: rig_get_freq(2088): vfo_opt=0, model=3073 icom_get_freq called for VFOB, curr_vfo=VFOB icom_get_freq: using vfo=VFOB icom.c(1656) trace set_vfo_curr: vfo=VFOB, curr_vfo=VFOB set_vfo_curr: curr_vfo now=VFOB icom.c(9429):set_vfo_curr returning2(0) icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication bus error Communication bus error 2023-01-11T10:35:22.382205-0500: icom_transaction: failed: icom_get_freq: using vfo=VFOB icom.c(1656) trace set_vfo_curr: vfo=VFOB, curr_vfo=VFOB set_vfo_curr: curr_vfo now=VFOB icom.c(9429):set_vfo_curr returning2(0) icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:22.382436-0500: -2:frame.c(455):icom_transaction returning(-13) Communication bus error 2023-01-11T10:35:22.382527-0500: icom.c(1667) trace 2023-01-11T10:35:22.382574-0500: set_vfo_curr: vfo=VFOB, curr_vfo=VFOB 2023-01-11T10:35:22.382659-0500: set_vfo_curr: curr_vfo now=VFOB 2023-01-11T10:35:22.382705-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:22.382798-0500: -3:icom.c(1685):icom_get_freq returning(-13) Communication bus error 2023-01-11T10:35:22.382961-0500: -4:rig_get_freq: elapsed=1105ms 2023-01-11T10:35:22.383045-0500: icom_rig_open: rig error getting frequency retry=1, err=Communication bus error Communication bus error icom.c(1667) trace set_vfo_curr: vfo=VFOB, curr_vfo=VFOB set_vfo_curr: curr_vfo now=VFOB icom.c(9429):set_vfo_curr returning2(0) rig_get_freq(2105): freqMainA=0, modeMainA=, widthMainA=0 rig_get_freq(2105): freqMainB=0, modeMainB=, widthMainB=0 rig_get_cache(259): vfo=VFOB, current_vfo=VFOB rig_get_cache(435): vfo=VFOB, freq=0, mode=, width=0 rig_set_cache_freq(122): vfo=VFOB, current_vfo=VFOB Communication bus error Communication bus error 2023-01-11T10:35:22.383241-0500: icom_rig_open trying power on 2023-01-11T10:35:22.383319-0500: rig_set_powerstat called status=1 2023-01-11T10:35:22.383366-0500: rig.c(6019) trace 2023-01-11T10:35:22.383411-0500: icom_set_powerstat called status=1 2023-01-11T10:35:23.383614-0500: write_block(): TX 175 bytes, method=2 2023-01-11T10:35:23.383703-0500: 0000 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:23.383767-0500: 0010 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:23.383827-0500: 0020 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:23.383925-0500: 0030 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:23.383988-0500: 0040 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:23.384073-0500: 0050 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:23.384136-0500: 0060 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:23.384196-0500: 0070 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:23.384275-0500: 0080 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:23.384376-0500: 0090 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:23.384454-0500: 00a0 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ............... 2023-01-11T10:35:23.384519-0500: -3:rig.c(1399):rig_close entered 2023-01-11T10:35:23.384579-0500: -2:icom.c(1128):icom_rig_close entered 2023-01-11T10:35:23.384654-0500: -2:icom.c(1150):icom_rig_close returning(0) 2023-01-11T10:35:23.384713-0500: -2:rig.c(7482):async_data_handler_stop entered 2023-01-11T10:35:23.384772-0500: -2:rig.c(7512):async_data_handler_stop returning(0) 2023-01-11T10:35:23.384898-0500: ser_close: restoring options 2023-01-11T10:35:23.385026-0500: rig_close(1535): 0x105f354 rs->comm_state==0?=0 2023-01-11T10:35:23.385088-0500: -3:rig.c(1537):rig_close returning(0) 2023-01-11T10:35:24.385279-0500: -3:rig.c(819):rig_open entered 2023-01-11T10:35:24.385463-0500: rig_settings_get_path: path=/home/pi/.config/hamlib_settings 2023-01-11T10:35:24.385592-0500: rig_settings_load_all: settings_file (/home/pi/.config/hamlib_settings): No such file or directory 2023-01-11T10:35:24.385660-0500: rig_open: cwd=/var/log 2023-01-11T10:35:24.385738-0500: rig_open: /var/log/hamlib_settings does not exist 2023-01-11T10:35:24.385795-0500: rig_open: async_data_enable=0, async_data_supported=1 2023-01-11T10:35:24.385853-0500: serial_open: /dev/serial/by-id/usb-Silicon_Labs_CP2102_USB_to_UART_Bridge_Controller_IC-7300_02020433-if00-port0 2023-01-11T10:35:24.388191-0500: serial_setup: tcgetattr 2023-01-11T10:35:24.388272-0500: serial_setup: cfmakeraw 2023-01-11T10:35:24.388324-0500: serial_setup: cfsetispeed=115200,0x1002 2023-01-11T10:35:24.388376-0500: serial_setup: cfsetospeed=115200,0x1002 2023-01-11T10:35:24.388426-0500: serial_setup: data_bits=8 2023-01-11T10:35:24.388474-0500: serial_setup: parity=0 2023-01-11T10:35:24.388522-0500: serial_setup: Handshake=None 2023-01-11T10:35:24.388576-0500: serial_setup: tcsetattr TCSANOW 2023-01-11T10:35:24.388644-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:24.439904-0500: -2:rig.c(7438):async_data_handler_start entered 2023-01-11T10:35:24.439991-0500: async_data_handler_start: async data support disabled since async_data_enabled=0 2023-01-11T10:35:24.440087-0500: -2:rig.c(7445):async_data_handler_start returning(0) 2023-01-11T10:35:24.440143-0500: rig.c(254):add_opened_rig returning2(0) 2023-01-11T10:35:24.440195-0500: rig_open: 0x105f354 rs->comm_state==1?=1 2023-01-11T10:35:24.440247-0500: -2:icom.c(986):icom_rig_open entered 2023-01-11T10:35:24.440299-0500: icom_rig_open: IC-7300 v20230109.10 2023-01-11T10:35:24.440350-0500: -1:icom.c(776):icom_get_usb_echo_off entered 2023-01-11T10:35:24.440403-0500: 0:frame.c(425):icom_transaction entered 2023-01-11T10:35:24.440454-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-11T10:35:24.440506-0500: 1:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:24.440557-0500: rig_flush: called for serial device 2023-01-11T10:35:24.440609-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:24.441799-0500: write_block(): TX 6 bytes, method=2 2023-01-11T10:35:24.441870-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:24.441921-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:24.443642-0500: read_string_generic(): RX 6 characters, direct=1 2023-01-11T10:35:24.443710-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:24.443761-0500: icom_one_transaction: frm_len=6, frm_len-1=fd, frm_len-2=03 2023-01-11T10:35:24.443815-0500: 1:frame.c(403):icom_one_transaction returning(0) 2023-01-11T10:35:24.443868-0500: 0:frame.c(455):icom_transaction returning(0) 2023-01-11T10:35:24.443919-0500: icom_get_usb_echo_off: ack_len=1 2023-01-11T10:35:24.443969-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:24.444204-0500: read_string_generic(): RX 6 characters, direct=1 2023-01-11T10:35:24.444261-0500: 0000 fe fe e0 94 fa fd ...... 2023-01-11T10:35:24.444309-0500: icom_get_usb_echo_off: USB echo on detected, get freq retval=6 2023-01-11T10:35:24.444361-0500: -1:icom.c(805):icom_get_usb_echo_off returning(0) 2023-01-11T10:35:24.444411-0500: icom_rig_open: echo status result=0 2023-01-11T10:35:24.444461-0500: icom_rig_open: echo status known, getting frequency 2023-01-11T10:35:24.444510-0500: icom_current_vfo: defaulting to VFOA as no XCHG or x25 available 2023-01-11T10:35:24.444563-0500: -1:rig.c(2729):rig_set_vfo entered 2023-01-11T10:35:24.444614-0500: rig_set_vfo called vfo=VFOA 2023-01-11T10:35:24.444666-0500: vfo_fixup:(from rig_set_vfo:2749) vfo=VFOA, vfo_curr=VFOB, split=0 2023-01-11T10:35:24.444719-0500: vfo_fixup:(from rig_set_vfo:2791) vfo=VFOA, vfo_curr=VFOB, split=0 2023-01-11T10:35:24.444769-0500: rig.c(2810) trace 2023-01-11T10:35:24.444818-0500: icom_set_vfo called vfo=VFOA 2023-01-11T10:35:24.444867-0500: icom_set_vfo: line#2863 2023-01-11T10:35:24.444915-0500: icom_set_vfo: line#3066 2023-01-11T10:35:24.444963-0500: 0:frame.c(425):icom_transaction entered 2023-01-11T10:35:24.445051-0500: icom_transaction: cmd=0x07, subcmd=0x00, payload_len=0 2023-01-11T10:35:24.445103-0500: 1:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:24.445152-0500: rig_flush: called for serial device 2023-01-11T10:35:24.445201-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:24.446385-0500: write_block(): TX 7 bytes, method=2 2023-01-11T10:35:24.446562-0500: 0000 fe fe 94 e0 07 00 fd ....... 2023-01-11T10:35:24.446690-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:25.447888-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-11T10:35:25.448103-0500: 1:frame.c(185):icom_one_transaction returning(-13) Communication bus error 2023-01-11T10:35:25.448386-0500: icom_transaction: retry=0: rig_set_vfo called vfo=VFOA vfo_fixup:(from rig_set_vfo:2749) vfo=VFOA, vfo_curr=VFOB, split=0 vfo_fixup:(from rig_set_vfo:2791) vfo=VFOA, vfo_curr=VFOB, split=0 rig.c(2810) trace icom_set_vfo called vfo=VFOA icom_set_vfo: line#2863 icom_set_vfo: line#3066 0:frame.c(425):icom_transaction entered icom_transaction: cmd=0x07, subcmd=0x00, payload_len=0 1:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 07 00 fd ....... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 1:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:25.549928-0500: icom_transaction: failed: vfo_fixup:(from rig_set_vfo:2791) vfo=VFOA, vfo_curr=VFOB, split=0 rig.c(2810) trace icom_set_vfo called vfo=VFOA icom_set_vfo: line#2863 icom_set_vfo: line#3066 0:frame.c(425):icom_transaction entered icom_transaction: cmd=0x07, subcmd=0x00, payload_len=0 1:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 07 00 fd ....... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 1:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:25.550890-0500: 0:frame.c(455):icom_transaction returning(-13) Communication bus error 2023-01-11T10:35:25.550991-0500: icom_set_vfo: line#3069 2023-01-11T10:35:25.551045-0500: icom.c(3073):icom_set_vfo returning2(-13) Communication bus error 2023-01-11T10:35:25.551194-0500: rig_set_vfo: set_vfo VFOA failed with ' 1:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 07 00 fd ....... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 1:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error 0:frame.c(455):icom_transaction returning(-13) Communication bus error icom_set_vfo: line#3069 icom.c(3073):icom_set_vfo returning2(-13) Communication bus error Communication bus error Communication bus error ' 2023-01-11T10:35:25.551486-0500: 0:rig.c(2886):rig_get_vfo entered 2023-01-11T10:35:25.551536-0500: rig_get_vfo: no get_vfo 2023-01-11T10:35:25.551595-0500: 0:rig_get_vfo: elapsed=0ms 2023-01-11T10:35:25.551650-0500: 0:rig.c(2909):rig_get_vfo returning(-11) Feature not available 2023-01-11T10:35:25.551702-0500: rig_set_vfo: Expiring all cache due to VFO change and no get_vfo 2023-01-11T10:35:25.551785-0500: rig_set_vfo: return -13, vfo=VFOA, curr_vfo=VFOB 2023-01-11T10:35:25.551844-0500: -1:rig_set_vfo: elapsed=1107ms 2023-01-11T10:35:25.551900-0500: -1:rig.c(2861):rig_set_vfo returning(-13) Communication bus error 2023-01-11T10:35:25.551959-0500: rig_get_freq(1992) called vfo=currVFO 2023-01-11T10:35:25.552054-0500: vfo_fixup:(from rig_get_freq:1998) vfo=currVFO, vfo_curr=VFOA, split=0 2023-01-11T10:35:25.552104-0500: vfo_fixup: Leaving currVFO alone 2023-01-11T10:35:25.552190-0500: rig.c(2001) vfo=currVFO, curr_vfo=VFOA 2023-01-11T10:35:25.552372-0500: rig_get_freq: cache miss age=10000ms, cached_vfo=VFOA, asked_vfo=VFOA, use_cached_freq=0 2023-01-11T10:35:25.552425-0500: rig_get_freq(2088): vfo_opt=0, model=3073 2023-01-11T10:35:25.552477-0500: icom_get_freq called for VFOA, curr_vfo=VFOA 2023-01-11T10:35:25.552527-0500: icom_get_freq: using vfo=VFOA 2023-01-11T10:35:25.552576-0500: icom.c(1656) trace 2023-01-11T10:35:25.552625-0500: set_vfo_curr: vfo=VFOA, curr_vfo=VFOA 2023-01-11T10:35:25.552674-0500: set_vfo_curr: curr_vfo now=VFOA 2023-01-11T10:35:25.552725-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:25.552776-0500: -1:frame.c(425):icom_transaction entered 2023-01-11T10:35:25.552828-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-11T10:35:25.552880-0500: 0:frame.c(138):icom_one_transaction entered 2023-01-11T10:35:25.552931-0500: rig_flush: called for serial device 2023-01-11T10:35:25.552984-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-11T10:35:25.554288-0500: write_block(): TX 6 bytes, method=2 2023-01-11T10:35:25.554369-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-11T10:35:25.554424-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-11T10:35:26.554918-0500: read_string_generic(): Timed out 1.000 seconds after 0 chars, direct=1 2023-01-11T10:35:26.555012-0500: 0:frame.c(185):icom_one_transaction returning(-13) Communication bus error 2023-01-11T10:35:26.555121-0500: icom_transaction: retry=0: rig_get_freq(2088): vfo_opt=0, model=3073 icom_get_freq called for VFOA, curr_vfo=VFOA icom_get_freq: using vfo=VFOA icom.c(1656) trace set_vfo_curr: vfo=VFOA, curr_vfo=VFOA set_vfo_curr: curr_vfo now=VFOA icom.c(9429):set_vfo_curr returning2(0) icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 0:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.000 seconds after 0 chars, direct=1 0:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:26.655602-0500: icom_transaction: failed: icom_get_freq: using vfo=VFOA icom.c(1656) trace set_vfo_curr: vfo=VFOA, curr_vfo=VFOA set_vfo_curr: curr_vfo now=VFOA icom.c(9429):set_vfo_curr returning2(0) icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 0:frame.c(138):icom_one_transaction entered rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.000 seconds after 0 chars, direct=1 0:frame.c(185):icom_one_transaction returning(-13) Communication bus error Communication bus error Communication bus error Communication bus error 2023-01-11T10:35:26.655858-0500: -1:frame.c(455):icom_transaction returning(-13) Communication bus error 2023-01-11T10:35:26.655957-0500: icom.c(1667) trace 2023-01-11T10:35:26.656011-0500: set_vfo_curr: vfo=VFOA, curr_vfo=VFOA 2023-01-11T10:35:26.656060-0500: set_vfo_curr: curr_vfo now=VFOA 2023-01-11T10:35:26.656110-0500: icom.c(9429):set_vfo_curr returning2(0) 2023-01-11T10:35:26.656165-0500: -2:icom.c(1685):icom_get_freq returning(-13) Communication bus error 2023-01-11T10:35:26.656349-0500: -3:rig_get_freq: elapsed=1104ms 2023-01-11T10:35:26.656443-0500: icom_rig_open: rig error getting frequency retry=1, err=Communication bus error Communication bus error icom.c(1667) trace set_vfo_curr: vfo=VFOA, curr_vfo=VFOA set_vfo_curr: curr_vfo now=VFOA icom.c(9429):set_vfo_curr returning2(0) rig_get_freq(2105): freqMainA=0, modeMainA=, widthMainA=0 rig_get_freq(2105): freqMainB=0, modeMainB=, widthMainB=0 rig_get_cache(259): vfo=VFOA, current_vfo=VFOA rig_get_cache(435): vfo=VFOA, freq=0, mode=, width=0 rig_set_cache_freq(122): vfo=VFOA, current_vfo=VFOA Communication bus error Communication bus error 2023-01-11T10:35:26.656655-0500: icom_rig_open trying power on 2023-01-11T10:35:26.656742-0500: rig_set_powerstat called status=1 2023-01-11T10:35:26.656789-0500: rig.c(6019) trace 2023-01-11T10:35:26.656836-0500: icom_set_powerstat called status=1 2023-01-11T10:35:27.657038-0500: write_block(): TX 175 bytes, method=2 2023-01-11T10:35:27.657127-0500: 0000 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:27.657184-0500: 0010 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:27.657240-0500: 0020 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:27.657296-0500: 0030 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:27.657350-0500: 0040 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:27.657407-0500: 0050 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:27.657463-0500: 0060 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:27.657519-0500: 0070 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:27.657577-0500: 0080 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:27.657635-0500: 0090 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-11T10:35:27.657705-0500: 00a0 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ............... 2023-01-11T10:35:27.657767-0500: -2:rig.c(1399):rig_close entered 2023-01-11T10:35:27.657824-0500: -1:icom.c(1128):icom_rig_close entered 2023-01-11T10:35:27.657880-0500: -1:icom.c(1150):icom_rig_close returning(0) 2023-01-11T10:35:27.657938-0500: -1:rig.c(7482):async_data_handler_stop entered 2023-01-11T10:35:27.657995-0500: -1:rig.c(7512):async_data_handler_stop returning(0) 2023-01-11T10:35:27.658051-0500: ser_close: restoring options 2023-01-11T10:35:27.658158-0500: rig_close(1535): 0x105f354 rs->comm_state==0?=0 2023-01-11T10:35:27.658220-0500: -2:rig.c(1537):rig_close returning(0) ^C pi@rigpi3:/var/log $ |
mdblack98
removed
the
needs test
mdblack98
added
needs test
|
Howard Nurse hfffn@sonic.net Wed, Jan 18 at 5:38 PM Powerstat appears to work well. Get freq error. pi@rigpi3:~/Downloads/Hamlib-master $ rigctl -m 3073 -r /dev/ttyUSB0 --set-conf=auto_power_on=1 -vvvvv -Z 2023-01-18T18:34:37.029289-0500: rigctl.c(445) Startup: rigctl -m 3073 -r /dev/ttyUSB0 --set-conf=auto_power_on=1 -vvvvv -Z 2023-01-18T18:34:37.030129-0500: rigctl Hamlib 4.6~git from indeterminate source revision. 2023-01-18T18:34:37.030580-0500: Report bugs to hamlib-developer@lists.sourceforge.net 2023-01-18T18:34:37.031242-0500: rig_check_rig_caps: p1=0xb6eafb60, p2=0xb6eb52ac, rig_model=0xb6eafb60, macro_name=0xb6eb52ac 2023-01-18T18:34:37.031715-0500: initrigs4_icom: _init called 2023-01-18T18:34:37.032180-0500: rig_init: rig_model=Icom IC-7300 2023-01-18T18:34:37.032516-0500: rig_init: rig has VFO_A 2023-01-18T18:34:37.032813-0500: rig_init: rig has VFO_B 2023-01-18T18:34:37.033067-0500: rig_init: rig has VFO_MEM 2023-01-18T18:34:37.033413-0500: 1:icom.c(623):icom_init entered 2023-01-18T18:34:37.033678-0500: icom_init: done 2023-01-18T18:34:37.034006-0500: 1:icom.c(724):icom_init returning(0) 2023-01-18T18:34:37.034280-0500: rig_token_lookup called for auto_power_on 2023-01-18T18:34:37.034544-0500: rig_confparam_lookup called for auto_power_on 2023-01-18T18:34:37.034815-0500: rig_token_lookup called for auto_power_on 2023-01-18T18:34:37.035078-0500: rig_confparam_lookup called for auto_power_on 2023-01-18T18:34:37.035429-0500: rig_set_conf called 2023-01-18T18:34:37.035744-0500: rig_confparam_lookup called for 1073741948 2023-01-18T18:34:37.036062-0500: rig_set_conf: auto_power_on='1' 2023-01-18T18:34:37.036482-0500: 1:rig.c(819):rig_open entered 2023-01-18T18:34:37.036850-0500: rig_settings_get_path: path=/home/pi/.config/hamlib_settings 2023-01-18T18:34:37.037261-0500: rig_settings_load_all: settings_file (/home/pi/.config/hamlib_settings): No such file or directory 2023-01-18T18:34:37.037613-0500: rig_open: cwd=/home/pi/Downloads/Hamlib-master 2023-01-18T18:34:37.038017-0500: rig_open: /home/pi/Downloads/Hamlib-master/hamlib_settings does not exist 2023-01-18T18:34:37.038350-0500: rig_open: async_data_enable=0, async_data_supported=1 2023-01-18T18:34:37.038633-0500: serial_open: /dev/ttyUSB0 2023-01-18T18:34:37.039723-0500: serial_setup: tcgetattr 2023-01-18T18:34:37.040004-0500: serial_setup: cfmakeraw 2023-01-18T18:34:37.040269-0500: serial_setup: cfsetispeed=115200,0x1002 2023-01-18T18:34:37.040538-0500: serial_setup: cfsetospeed=115200,0x1002 2023-01-18T18:34:37.040803-0500: serial_setup: data_bits=8 2023-01-18T18:34:37.041059-0500: serial_setup: parity=0 2023-01-18T18:34:37.041319-0500: serial_setup: Handshake=None 2023-01-18T18:34:37.041619-0500: serial_setup: tcsetattr TCSANOW 2023-01-18T18:34:37.041994-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:37.093629-0500: 2:rig.c(7448):async_data_handler_start entered 2023-01-18T18:34:37.094055-0500: async_data_handler_start: async data support disabled since async_data_enabled=0 2023-01-18T18:34:37.094385-0500: 2:rig.c(7455):async_data_handler_start returning(0) 2023-01-18T18:34:37.094761-0500: rig.c(254):add_opened_rig returning2(0) 2023-01-18T18:34:37.095085-0500: rig_open: 0x8df354 rs->comm_state==1?=1 2023-01-18T18:34:37.095490-0500: 2:icom.c(987):icom_rig_open entered 2023-01-18T18:34:37.095811-0500: icom_rig_open: IC-7300 v20230118.10 2023-01-18T18:34:37.096132-0500: icom_rig_open asking for power on ***************************************** 2023-01-18T18:34:37.096547-0500: 3:rig.c(6014):rig_set_powerstat entered 2023-01-18T18:34:37.096874-0500: rig_set_powerstat called status=1 2023-01-18T18:34:37.097192-0500: rig.c(6028) trace 2023-01-18T18:34:37.097507-0500: icom_set_powerstat called status=1 2023-01-18T18:34:37.097868-0500: write_block(): TX 175 bytes, method=2 2023-01-18T18:34:37.098208-0500: 0000 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.098542-0500: 0010 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.098875-0500: 0020 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.099202-0500: 0030 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.099531-0500: 0040 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.099860-0500: 0050 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.100225-0500: 0060 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.100586-0500: 0070 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.100932-0500: 0080 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.101283-0500: 0090 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.101631-0500: 00a0 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ............... 2023-01-18T18:34:37.101990-0500: 4:frame.c(425):icom_transaction entered 2023-01-18T18:34:37.102322-0500: icom_transaction: cmd=0x18, subcmd=0x01, payload_len=0 2023-01-18T18:34:37.102682-0500: 5:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:37.103012-0500: rig_flush: called for serial device 2023-01-18T18:34:37.103354-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:37.104798-0500: write_block(): TX 7 bytes, method=2 2023-01-18T18:34:37.105135-0500: 0000 fe fe 94 e0 18 01 fd ....... 2023-01-18T18:34:37.105464-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:37.115845-0500: read_string_generic(): RX 64 characters, direct=1 2023-01-18T18:34:37.116207-0500: 0000 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.116538-0500: 0010 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.116868-0500: 0020 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.117199-0500: 0030 fe fe fe fe fe fe fe fe fe fe fe 94 e0 18 01 fd ................ 2023-01-18T18:34:37.117526-0500: icom_one_transaction: frm_len=64, frm_len-1=fd, frm_len-2=01 2023-01-18T18:34:37.117941-0500: 5:frame.c(403):icom_one_transaction returning(0) 2023-01-18T18:34:37.118272-0500: 4:frame.c(455):icom_transaction returning(0) 2023-01-18T18:34:38.118720-0500: 4:icom.c(777):icom_get_usb_echo_off entered 2023-01-18T18:34:38.118813-0500: 5:frame.c(425):icom_transaction entered 2023-01-18T18:34:38.118871-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-18T18:34:38.118927-0500: 6:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:38.118983-0500: rig_flush: called for serial device 2023-01-18T18:34:38.119037-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:38.120355-0500: 0000 fe fe e0 94 fb fd ...... 2023-01-18T18:34:38.120458-0500: write_block(): TX 6 bytes, method=2 2023-01-18T18:34:38.120514-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-18T18:34:38.120584-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:39.121717-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-18T18:34:39.121855-0500: 6:frame.c(294):icom_one_transaction returning(-5) Communication timed out 2023-01-18T18:34:39.121974-0500: icom_transaction: retry=0: 0020 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 0030 fe fe fe fe fe fe fe fe fe fe fe 94 e0 18 01 fd ................ icom_one_transaction: frm_len=64, frm_len-1=fd, frm_len-2=01 icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 0000 fe fe e0 94 fb fd ...... write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out 2023-01-18T18:34:39.222435-0500: icom_transaction: failed: icom_one_transaction: frm_len=64, frm_len-1=fd, frm_len-2=01 icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 0000 fe fe e0 94 fb fd ...... write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out Communication timed out 2023-01-18T18:34:39.222744-0500: 5:frame.c(455):icom_transaction returning(-5) Communication timed out 2023-01-18T18:34:39.222858-0500: 4:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out 2023-01-18T18:34:39.222920-0500: rig_flush: called for serial device 2023-01-18T18:34:39.222973-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:39.224133-0500: 3:rig.c(6032):rig_set_powerstat returning(0) 2023-01-18T18:34:39.224195-0500: icom_rig_open asking for power on #2 ======================================= 2023-01-18T18:34:39.224250-0500: 3:icom.c(777):icom_get_usb_echo_off entered 2023-01-18T18:34:39.224304-0500: 4:frame.c(425):icom_transaction entered 2023-01-18T18:34:39.224364-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-18T18:34:39.224415-0500: 5:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:39.224465-0500: rig_flush: called for serial device 2023-01-18T18:34:39.224517-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:39.225706-0500: write_block(): TX 6 bytes, method=2 2023-01-18T18:34:39.225775-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-18T18:34:39.225826-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:40.226964-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-18T18:34:40.227059-0500: 5:frame.c(294):icom_one_transaction returning(-5) Communication timed out 2023-01-18T18:34:40.227172-0500: icom_transaction: retry=0: 4:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 3:rig.c(6032):rig_set_powerstat returning(0) icom_rig_open asking for power on #2 ======================================= 3:icom.c(777):icom_get_usb_echo_off entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out 2023-01-18T18:34:40.327677-0500: icom_transaction: failed: rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 3:rig.c(6032):rig_set_powerstat returning(0) icom_rig_open asking for power on #2 ======================================= 3:icom.c(777):icom_get_usb_echo_off entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out Communication timed out 2023-01-18T18:34:40.327932-0500: 4:frame.c(455):icom_transaction returning(-5) Communication timed out 2023-01-18T18:34:40.328037-0500: 3:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out 2023-01-18T18:34:40.328094-0500: icom_rig_open: echo status result=-5 2023-01-18T18:34:40.328144-0500: icom_rig_open: echo status unknown 2023-01-18T18:34:40.828306-0500: 3:icom.c(777):icom_get_usb_echo_off entered 2023-01-18T18:34:40.828394-0500: 4:frame.c(425):icom_transaction entered 2023-01-18T18:34:40.828445-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-18T18:34:40.828497-0500: 5:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:40.828548-0500: rig_flush: called for serial device 2023-01-18T18:34:40.828598-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:40.829796-0500: write_block(): TX 6 bytes, method=2 2023-01-18T18:34:40.829864-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-18T18:34:40.829916-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:41.831063-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-18T18:34:41.831161-0500: 5:frame.c(294):icom_one_transaction returning(-5) Communication timed out 2023-01-18T18:34:41.831271-0500: icom_transaction: retry=0: 4:frame.c(455):icom_transaction returning(-5) Communication timed out 3:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out icom_rig_open: echo status result=-5 icom_rig_open: echo status unknown 3:icom.c(777):icom_get_usb_echo_off entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out 2023-01-18T18:34:41.931720-0500: icom_transaction: failed: 3:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out icom_rig_open: echo status result=-5 icom_rig_open: echo status unknown 3:icom.c(777):icom_get_usb_echo_off entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out Communication timed out 2023-01-18T18:34:41.931972-0500: 4:frame.c(455):icom_transaction returning(-5) Communication timed out 2023-01-18T18:34:41.932075-0500: 3:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out 2023-01-18T18:34:41.932132-0500: icom_rig_open: echo status result=-5 2023-01-18T18:34:41.932182-0500: icom_rig_open: echo status unknown 2023-01-18T18:34:41.932231-0500: 2:icom.c(1127):icom_rig_open returning(0) 2023-01-18T18:34:41.932281-0500: rig.c(1286) trace 2023-01-18T18:34:41.932341-0500: rig_open: vfo_curr=currVFO, tx_vfo=TX 2023-01-18T18:34:41.932390-0500: rig_open: default vfo = currVFO 2023-01-18T18:34:41.932454-0500: rig_get_freq(1996) called vfo=VFOA 2023-01-18T18:34:41.932560-0500: vfo_fixup:(from rig_get_freq:2002) vfo=VFOA, vfo_curr=currVFO, split=0 2023-01-18T18:34:41.932611-0500: rig.c(2005) vfo=VFOA, curr_vfo=currVFO 2023-01-18T18:34:41.932836-0500: rig_get_freq: cache miss age=1000000ms, cached_vfo=VFOA, asked_vfo=VFOA, use_cached_freq=0 2023-01-18T18:34:41.932900-0500: rig_get_freq(2092): vfo_opt=0, model=3073 2023-01-18T18:34:41.932953-0500: icom_get_freq called for VFOA, curr_vfo=currVFO 2023-01-18T18:34:41.933002-0500: icom_get_freq: using vfo=VFOA 2023-01-18T18:34:41.933052-0500: 2:frame.c(425):icom_transaction entered 2023-01-18T18:34:41.933104-0500: icom_transaction: cmd=0x25, subcmd=0x00, payload_len=0 2023-01-18T18:34:41.933165-0500: 3:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:41.933218-0500: rig_flush: called for serial device 2023-01-18T18:34:41.933272-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:41.934465-0500: write_block(): TX 7 bytes, method=2 2023-01-18T18:34:41.934535-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:41.934587-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:41.937135-0500: read_string_generic(): RX 7 characters, direct=1 2023-01-18T18:34:41.937196-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:41.937250-0500: icom_one_transaction: frm_len=7, frm_len-1=fd, frm_len-2=00 2023-01-18T18:34:41.937309-0500: 3:frame.c(403):icom_one_transaction returning(0) 2023-01-18T18:34:41.937365-0500: 2:frame.c(455):icom_transaction returning(0) 2023-01-18T18:34:41.937421-0500: icom_get_freq: wrong frame len=0 2023-01-18T18:34:41.937487-0500: 1:icom.c(1732):icom_get_freq returning(-9) Command rejected by the rig 2023-01-18T18:34:41.937672-0500: 0:rig_get_freq: elapsed=5ms 2023-01-18T18:34:41.937730-0500: 0:rig.c(1381):rig_open returning(0) Opened rig model 3073, 'IC-7300' 2023-01-18T18:34:41.937840-0500: Backend version: 20230118.10, Status: Stable 2023-01-18T18:34:41.937994-0500: rigctl_parse: called, interactive=1 Rig command: f 2023-01-18T18:34:44.596312-0500: rigctl_parse: input_line: f 2023-01-18T18:34:44.596425-0500: rigctl_parse: vfo_opt=0 2023-01-18T18:34:44.596492-0500: 0:rig.c(6054):rig_get_powerstat entered 2023-01-18T18:34:44.596549-0500: rig.c(6074) trace 2023-01-18T18:34:44.596600-0500: 1:icom.c(8119):icom_get_powerstat entered 2023-01-18T18:34:44.596660-0500: rig_get_freq(1996) called vfo=VFOA 2023-01-18T18:34:44.596763-0500: vfo_fixup:(from rig_get_freq:2002) vfo=VFOA, vfo_curr=currVFO, split=0 2023-01-18T18:34:44.596820-0500: rig.c(2005) vfo=VFOA, curr_vfo=currVFO 2023-01-18T18:34:44.596995-0500: rig_get_freq: cache miss age=12659ms, cached_vfo=VFOA, asked_vfo=VFOA, use_cached_freq=0 2023-01-18T18:34:44.597051-0500: rig_get_freq(2092): vfo_opt=0, model=3073 2023-01-18T18:34:44.597102-0500: icom_get_freq called for VFOA, curr_vfo=currVFO 2023-01-18T18:34:44.597154-0500: icom_get_freq: using vfo=VFOA 2023-01-18T18:34:44.597206-0500: 2:frame.c(425):icom_transaction entered 2023-01-18T18:34:44.597256-0500: icom_transaction: cmd=0x25, subcmd=0x00, payload_len=0 2023-01-18T18:34:44.597308-0500: 3:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:44.597363-0500: rig_flush: called for serial device 2023-01-18T18:34:44.597416-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:44.598871-0500: 0000 fe fe e0 94 25 00 00 40 07 14 00 fd ....%..@.... 2023-01-18T18:34:44.598965-0500: write_block(): TX 7 bytes, method=2 2023-01-18T18:34:44.599025-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:44.599076-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:44.600349-0500: read_string_generic(): RX 7 characters, direct=1 2023-01-18T18:34:44.600411-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:44.600466-0500: icom_one_transaction: frm_len=7, frm_len-1=fd, frm_len-2=00 2023-01-18T18:34:44.600521-0500: 3:frame.c(403):icom_one_transaction returning(0) 2023-01-18T18:34:44.600577-0500: 2:frame.c(455):icom_transaction returning(0) 2023-01-18T18:34:44.600629-0500: icom_get_freq: wrong frame len=0 2023-01-18T18:34:44.600684-0500: 1:icom.c(1732):icom_get_freq returning(-9) Command rejected by the rig 2023-01-18T18:34:44.600858-0500: 0:rig_get_freq: elapsed=4ms 2023-01-18T18:34:44.600916-0500: 0:rig.c(6076):rig_get_powerstat returning(-9) Command rejected by the rig 2023-01-18T18:34:44.600977-0500: rigctl_parse: rig_powerstat is not on = 0 2023-01-18T18:34:44.601034-0500: 0:rigctl_parse.c(2127):rigctl_get_freq entered 2023-01-18T18:34:44.601094-0500: rig_get_freq(1996) called vfo=currVFO 2023-01-18T18:34:44.601183-0500: vfo_fixup:(from rig_get_freq:2002) vfo=currVFO, vfo_curr=currVFO, split=0 2023-01-18T18:34:44.601236-0500: vfo_fixup: Leaving currVFO alone 2023-01-18T18:34:44.601287-0500: rig.c(2005) vfo=currVFO, curr_vfo=currVFO 2023-01-18T18:34:44.601457-0500: rig_get_freq: cache miss age=10000ms, cached_vfo=currVFO, asked_vfo=currVFO, use_cached_freq=0 2023-01-18T18:34:44.601512-0500: rig_get_freq(2092): vfo_opt=0, model=3073 2023-01-18T18:34:44.601560-0500: icom_get_freq called for currVFO, curr_vfo=currVFO 2023-01-18T18:34:44.601613-0500: icom_get_freq: using vfo=currVFO 2023-01-18T18:34:44.601665-0500: 1:frame.c(425):icom_transaction entered 2023-01-18T18:34:44.601715-0500: icom_transaction: cmd=0x25, subcmd=0x00, payload_len=0 2023-01-18T18:34:44.601769-0500: 2:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:44.601821-0500: rig_flush: called for serial device 2023-01-18T18:34:44.601870-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:44.603342-0500: 0000 fe fe e0 94 25 00 00 40 07 14 00 fd ....%..@.... 2023-01-18T18:34:44.603448-0500: write_block(): TX 7 bytes, method=2 2023-01-18T18:34:44.603508-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:44.603561-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:44.604842-0500: read_string_generic(): RX 7 characters, direct=1 2023-01-18T18:34:44.604916-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:44.604974-0500: icom_one_transaction: frm_len=7, frm_len-1=fd, frm_len-2=00 2023-01-18T18:34:44.605035-0500: 2:frame.c(403):icom_one_transaction returning(0) 2023-01-18T18:34:44.605094-0500: 1:frame.c(455):icom_transaction returning(0) 2023-01-18T18:34:44.605150-0500: icom_get_freq: wrong frame len=0 2023-01-18T18:34:44.605207-0500: 0:icom.c(1732):icom_get_freq returning(-9) Command rejected by the rig 2023-01-18T18:34:44.605397-0500: -1:rig_get_freq: elapsed=4ms 2023-01-18T18:34:44.605470-0500: -1:rigctl_parse.c(2133):rigctl_get_freq returning(-9) Command rejected by the rig get_freq: error = write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 25 00 fd ....%.. read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): RX 7 characters, direct=1 0000 fe fe 94 e0 25 00 fd ....%.. icom_one_transaction: frm_len=7, frm_len-1=fd, frm_len-2=00 2:frame.c(403):icom_one_transaction returning(0) 1:frame.c(455):icom_transaction returning(0) icom_get_freq: wrong frame len=0 0:icom.c(1732):icom_get_freq returning(-9) Command rejected by the rig rig_get_freq(2109): freqMainA=0, modeMainA=, widthMainA=0 rig_get_freq(2109): freqMainB=0, modeMainB=, widthMainB=0 rig_get_cache(259): vfo=currVFO, current_vfo=currVFO rig_get_cache(435): vfo=VFOA, freq=0, mode=, width=0 rig_set_cache_freq(122): vfo=currVFO, current_vfo=currVFO Command rejected by the rig 2023-01-18T18:34:44.605847-0500: rigctl_parse: called, interactive=1 Rig command: From: Black Michael [mailto:mdblack98@yahoo.com] Try the latest please -- cleaned up things a bit and seems better behaved here and simpler. Mike W9MDB On Tuesday, January 17, 2023 at 04:26:58 PM CST, Howard Nurse <hlnurse@cmmsft.com> wrote: Mike, did I miss your latest response on the powerstat issue for the 7300? --Howard Wed, Jan 18 at 5:38 PM Powerstat appears to work well. Get freq error. pi@rigpi3:~/Downloads/Hamlib-master $ rigctl -m 3073 -r /dev/ttyUSB0 --set-conf=auto_power_on=1 -vvvvv -Z 2023-01-18T18:34:37.029289-0500: rigctl.c(445) Startup: rigctl -m 3073 -r /dev/ttyUSB0 --set-conf=auto_power_on=1 -vvvvv -Z 2023-01-18T18:34:37.030129-0500: rigctl Hamlib 4.6~git from indeterminate source revision. 2023-01-18T18:34:37.030580-0500: Report bugs to hamlib-developer@lists.sourceforge.net 2023-01-18T18:34:37.031242-0500: rig_check_rig_caps: p1=0xb6eafb60, p2=0xb6eb52ac, rig_model=0xb6eafb60, macro_name=0xb6eb52ac 2023-01-18T18:34:37.031715-0500: initrigs4_icom: _init called 2023-01-18T18:34:37.032180-0500: rig_init: rig_model=Icom IC-7300 2023-01-18T18:34:37.032516-0500: rig_init: rig has VFO_A 2023-01-18T18:34:37.032813-0500: rig_init: rig has VFO_B 2023-01-18T18:34:37.033067-0500: rig_init: rig has VFO_MEM 2023-01-18T18:34:37.033413-0500: 1:icom.c(623):icom_init entered 2023-01-18T18:34:37.033678-0500: icom_init: done 2023-01-18T18:34:37.034006-0500: 1:icom.c(724):icom_init returning(0) 2023-01-18T18:34:37.034280-0500: rig_token_lookup called for auto_power_on 2023-01-18T18:34:37.034544-0500: rig_confparam_lookup called for auto_power_on 2023-01-18T18:34:37.034815-0500: rig_token_lookup called for auto_power_on 2023-01-18T18:34:37.035078-0500: rig_confparam_lookup called for auto_power_on 2023-01-18T18:34:37.035429-0500: rig_set_conf called 2023-01-18T18:34:37.035744-0500: rig_confparam_lookup called for 1073741948 2023-01-18T18:34:37.036062-0500: rig_set_conf: auto_power_on='1' 2023-01-18T18:34:37.036482-0500: 1:rig.c(819):rig_open entered 2023-01-18T18:34:37.036850-0500: rig_settings_get_path: path=/home/pi/.config/hamlib_settings 2023-01-18T18:34:37.037261-0500: rig_settings_load_all: settings_file (/home/pi/.config/hamlib_settings): No such file or directory 2023-01-18T18:34:37.037613-0500: rig_open: cwd=/home/pi/Downloads/Hamlib-master 2023-01-18T18:34:37.038017-0500: rig_open: /home/pi/Downloads/Hamlib-master/hamlib_settings does not exist 2023-01-18T18:34:37.038350-0500: rig_open: async_data_enable=0, async_data_supported=1 2023-01-18T18:34:37.038633-0500: serial_open: /dev/ttyUSB0 2023-01-18T18:34:37.039723-0500: serial_setup: tcgetattr 2023-01-18T18:34:37.040004-0500: serial_setup: cfmakeraw 2023-01-18T18:34:37.040269-0500: serial_setup: cfsetispeed=115200,0x1002 2023-01-18T18:34:37.040538-0500: serial_setup: cfsetospeed=115200,0x1002 2023-01-18T18:34:37.040803-0500: serial_setup: data_bits=8 2023-01-18T18:34:37.041059-0500: serial_setup: parity=0 2023-01-18T18:34:37.041319-0500: serial_setup: Handshake=None 2023-01-18T18:34:37.041619-0500: serial_setup: tcsetattr TCSANOW 2023-01-18T18:34:37.041994-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:37.093629-0500: 2:rig.c(7448):async_data_handler_start entered 2023-01-18T18:34:37.094055-0500: async_data_handler_start: async data support disabled since async_data_enabled=0 2023-01-18T18:34:37.094385-0500: 2:rig.c(7455):async_data_handler_start returning(0) 2023-01-18T18:34:37.094761-0500: rig.c(254):add_opened_rig returning2(0) 2023-01-18T18:34:37.095085-0500: rig_open: 0x8df354 rs->comm_state==1?=1 2023-01-18T18:34:37.095490-0500: 2:icom.c(987):icom_rig_open entered 2023-01-18T18:34:37.095811-0500: icom_rig_open: IC-7300 v20230118.10 2023-01-18T18:34:37.096132-0500: icom_rig_open asking for power on ***************************************** 2023-01-18T18:34:37.096547-0500: 3:rig.c(6014):rig_set_powerstat entered 2023-01-18T18:34:37.096874-0500: rig_set_powerstat called status=1 2023-01-18T18:34:37.097192-0500: rig.c(6028) trace 2023-01-18T18:34:37.097507-0500: icom_set_powerstat called status=1 2023-01-18T18:34:37.097868-0500: write_block(): TX 175 bytes, method=2 2023-01-18T18:34:37.098208-0500: 0000 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.098542-0500: 0010 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.098875-0500: 0020 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.099202-0500: 0030 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.099531-0500: 0040 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.099860-0500: 0050 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.100225-0500: 0060 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.100586-0500: 0070 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.100932-0500: 0080 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.101283-0500: 0090 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.101631-0500: 00a0 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ............... 2023-01-18T18:34:37.101990-0500: 4:frame.c(425):icom_transaction entered 2023-01-18T18:34:37.102322-0500: icom_transaction: cmd=0x18, subcmd=0x01, payload_len=0 2023-01-18T18:34:37.102682-0500: 5:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:37.103012-0500: rig_flush: called for serial device 2023-01-18T18:34:37.103354-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:37.104798-0500: write_block(): TX 7 bytes, method=2 2023-01-18T18:34:37.105135-0500: 0000 fe fe 94 e0 18 01 fd ....... 2023-01-18T18:34:37.105464-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:37.115845-0500: read_string_generic(): RX 64 characters, direct=1 2023-01-18T18:34:37.116207-0500: 0000 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.116538-0500: 0010 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.116868-0500: 0020 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 2023-01-18T18:34:37.117199-0500: 0030 fe fe fe fe fe fe fe fe fe fe fe 94 e0 18 01 fd ................ 2023-01-18T18:34:37.117526-0500: icom_one_transaction: frm_len=64, frm_len-1=fd, frm_len-2=01 2023-01-18T18:34:37.117941-0500: 5:frame.c(403):icom_one_transaction returning(0) 2023-01-18T18:34:37.118272-0500: 4:frame.c(455):icom_transaction returning(0) 2023-01-18T18:34:38.118720-0500: 4:icom.c(777):icom_get_usb_echo_off entered 2023-01-18T18:34:38.118813-0500: 5:frame.c(425):icom_transaction entered 2023-01-18T18:34:38.118871-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-18T18:34:38.118927-0500: 6:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:38.118983-0500: rig_flush: called for serial device 2023-01-18T18:34:38.119037-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:38.120355-0500: 0000 fe fe e0 94 fb fd ...... 2023-01-18T18:34:38.120458-0500: write_block(): TX 6 bytes, method=2 2023-01-18T18:34:38.120514-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-18T18:34:38.120584-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:39.121717-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-18T18:34:39.121855-0500: 6:frame.c(294):icom_one_transaction returning(-5) Communication timed out 2023-01-18T18:34:39.121974-0500: icom_transaction: retry=0: 0020 fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe fe ................ 0030 fe fe fe fe fe fe fe fe fe fe fe 94 e0 18 01 fd ................ icom_one_transaction: frm_len=64, frm_len-1=fd, frm_len-2=01 icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 0000 fe fe e0 94 fb fd ...... write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out 2023-01-18T18:34:39.222435-0500: icom_transaction: failed: icom_one_transaction: frm_len=64, frm_len-1=fd, frm_len-2=01 icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 0000 fe fe e0 94 fb fd ...... write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out Communication timed out 2023-01-18T18:34:39.222744-0500: 5:frame.c(455):icom_transaction returning(-5) Communication timed out 2023-01-18T18:34:39.222858-0500: 4:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out 2023-01-18T18:34:39.222920-0500: rig_flush: called for serial device 2023-01-18T18:34:39.222973-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:39.224133-0500: 3:rig.c(6032):rig_set_powerstat returning(0) 2023-01-18T18:34:39.224195-0500: icom_rig_open asking for power on #2 ======================================= 2023-01-18T18:34:39.224250-0500: 3:icom.c(777):icom_get_usb_echo_off entered 2023-01-18T18:34:39.224304-0500: 4:frame.c(425):icom_transaction entered 2023-01-18T18:34:39.224364-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-18T18:34:39.224415-0500: 5:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:39.224465-0500: rig_flush: called for serial device 2023-01-18T18:34:39.224517-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:39.225706-0500: write_block(): TX 6 bytes, method=2 2023-01-18T18:34:39.225775-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-18T18:34:39.225826-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:40.226964-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-18T18:34:40.227059-0500: 5:frame.c(294):icom_one_transaction returning(-5) Communication timed out 2023-01-18T18:34:40.227172-0500: icom_transaction: retry=0: 4:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 3:rig.c(6032):rig_set_powerstat returning(0) icom_rig_open asking for power on #2 ======================================= 3:icom.c(777):icom_get_usb_echo_off entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out 2023-01-18T18:34:40.327677-0500: icom_transaction: failed: rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 3:rig.c(6032):rig_set_powerstat returning(0) icom_rig_open asking for power on #2 ======================================= 3:icom.c(777):icom_get_usb_echo_off entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out Communication timed out 2023-01-18T18:34:40.327932-0500: 4:frame.c(455):icom_transaction returning(-5) Communication timed out 2023-01-18T18:34:40.328037-0500: 3:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out 2023-01-18T18:34:40.328094-0500: icom_rig_open: echo status result=-5 2023-01-18T18:34:40.328144-0500: icom_rig_open: echo status unknown 2023-01-18T18:34:40.828306-0500: 3:icom.c(777):icom_get_usb_echo_off entered 2023-01-18T18:34:40.828394-0500: 4:frame.c(425):icom_transaction entered 2023-01-18T18:34:40.828445-0500: icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 2023-01-18T18:34:40.828497-0500: 5:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:40.828548-0500: rig_flush: called for serial device 2023-01-18T18:34:40.828598-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:40.829796-0500: write_block(): TX 6 bytes, method=2 2023-01-18T18:34:40.829864-0500: 0000 fe fe 94 e0 03 fd ...... 2023-01-18T18:34:40.829916-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:41.831063-0500: read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 2023-01-18T18:34:41.831161-0500: 5:frame.c(294):icom_one_transaction returning(-5) Communication timed out 2023-01-18T18:34:41.831271-0500: icom_transaction: retry=0: 4:frame.c(455):icom_transaction returning(-5) Communication timed out 3:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out icom_rig_open: echo status result=-5 icom_rig_open: echo status unknown 3:icom.c(777):icom_get_usb_echo_off entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out 2023-01-18T18:34:41.931720-0500: icom_transaction: failed: 3:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out icom_rig_open: echo status result=-5 icom_rig_open: echo status unknown 3:icom.c(777):icom_get_usb_echo_off entered icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0 rig_flush: called for serial device read_string_generic called, rxmax=4095 direct=1, expected_len=1 write_block(): TX 6 bytes, method=2 0000 fe fe 94 e0 03 fd ...... read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): Timed out 1.001 seconds after 0 chars, direct=1 Communication timed out Communication timed out Communication timed out 2023-01-18T18:34:41.931972-0500: 4:frame.c(455):icom_transaction returning(-5) Communication timed out 2023-01-18T18:34:41.932075-0500: 3:icom.c(785):icom_get_usb_echo_off returning(-5) Communication timed out 2023-01-18T18:34:41.932132-0500: icom_rig_open: echo status result=-5 2023-01-18T18:34:41.932182-0500: icom_rig_open: echo status unknown 2023-01-18T18:34:41.932231-0500: 2:icom.c(1127):icom_rig_open returning(0) 2023-01-18T18:34:41.932281-0500: rig.c(1286) trace 2023-01-18T18:34:41.932341-0500: rig_open: vfo_curr=currVFO, tx_vfo=TX 2023-01-18T18:34:41.932390-0500: rig_open: default vfo = currVFO 2023-01-18T18:34:41.932454-0500: rig_get_freq(1996) called vfo=VFOA 2023-01-18T18:34:41.932560-0500: vfo_fixup:(from rig_get_freq:2002) vfo=VFOA, vfo_curr=currVFO, split=0 2023-01-18T18:34:41.932611-0500: rig.c(2005) vfo=VFOA, curr_vfo=currVFO 2023-01-18T18:34:41.932836-0500: rig_get_freq: cache miss age=1000000ms, cached_vfo=VFOA, asked_vfo=VFOA, use_cached_freq=0 2023-01-18T18:34:41.932900-0500: rig_get_freq(2092): vfo_opt=0, model=3073 2023-01-18T18:34:41.932953-0500: icom_get_freq called for VFOA, curr_vfo=currVFO 2023-01-18T18:34:41.933002-0500: icom_get_freq: using vfo=VFOA 2023-01-18T18:34:41.933052-0500: 2:frame.c(425):icom_transaction entered 2023-01-18T18:34:41.933104-0500: icom_transaction: cmd=0x25, subcmd=0x00, payload_len=0 2023-01-18T18:34:41.933165-0500: 3:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:41.933218-0500: rig_flush: called for serial device 2023-01-18T18:34:41.933272-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:41.934465-0500: write_block(): TX 7 bytes, method=2 2023-01-18T18:34:41.934535-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:41.934587-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:41.937135-0500: read_string_generic(): RX 7 characters, direct=1 2023-01-18T18:34:41.937196-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:41.937250-0500: icom_one_transaction: frm_len=7, frm_len-1=fd, frm_len-2=00 2023-01-18T18:34:41.937309-0500: 3:frame.c(403):icom_one_transaction returning(0) 2023-01-18T18:34:41.937365-0500: 2:frame.c(455):icom_transaction returning(0) 2023-01-18T18:34:41.937421-0500: icom_get_freq: wrong frame len=0 2023-01-18T18:34:41.937487-0500: 1:icom.c(1732):icom_get_freq returning(-9) Command rejected by the rig 2023-01-18T18:34:41.937672-0500: 0:rig_get_freq: elapsed=5ms 2023-01-18T18:34:41.937730-0500: 0:rig.c(1381):rig_open returning(0) Opened rig model 3073, 'IC-7300' 2023-01-18T18:34:41.937840-0500: Backend version: 20230118.10, Status: Stable 2023-01-18T18:34:41.937994-0500: rigctl_parse: called, interactive=1 Rig command: f 2023-01-18T18:34:44.596312-0500: rigctl_parse: input_line: f 2023-01-18T18:34:44.596425-0500: rigctl_parse: vfo_opt=0 2023-01-18T18:34:44.596492-0500: 0:rig.c(6054):rig_get_powerstat entered 2023-01-18T18:34:44.596549-0500: rig.c(6074) trace 2023-01-18T18:34:44.596600-0500: 1:icom.c(8119):icom_get_powerstat entered 2023-01-18T18:34:44.596660-0500: rig_get_freq(1996) called vfo=VFOA 2023-01-18T18:34:44.596763-0500: vfo_fixup:(from rig_get_freq:2002) vfo=VFOA, vfo_curr=currVFO, split=0 2023-01-18T18:34:44.596820-0500: rig.c(2005) vfo=VFOA, curr_vfo=currVFO 2023-01-18T18:34:44.596995-0500: rig_get_freq: cache miss age=12659ms, cached_vfo=VFOA, asked_vfo=VFOA, use_cached_freq=0 2023-01-18T18:34:44.597051-0500: rig_get_freq(2092): vfo_opt=0, model=3073 2023-01-18T18:34:44.597102-0500: icom_get_freq called for VFOA, curr_vfo=currVFO 2023-01-18T18:34:44.597154-0500: icom_get_freq: using vfo=VFOA 2023-01-18T18:34:44.597206-0500: 2:frame.c(425):icom_transaction entered 2023-01-18T18:34:44.597256-0500: icom_transaction: cmd=0x25, subcmd=0x00, payload_len=0 2023-01-18T18:34:44.597308-0500: 3:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:44.597363-0500: rig_flush: called for serial device 2023-01-18T18:34:44.597416-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:44.598871-0500: 0000 fe fe e0 94 25 00 00 40 07 14 00 fd ....%..@.... 2023-01-18T18:34:44.598965-0500: write_block(): TX 7 bytes, method=2 2023-01-18T18:34:44.599025-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:44.599076-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:44.600349-0500: read_string_generic(): RX 7 characters, direct=1 2023-01-18T18:34:44.600411-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:44.600466-0500: icom_one_transaction: frm_len=7, frm_len-1=fd, frm_len-2=00 2023-01-18T18:34:44.600521-0500: 3:frame.c(403):icom_one_transaction returning(0) 2023-01-18T18:34:44.600577-0500: 2:frame.c(455):icom_transaction returning(0) 2023-01-18T18:34:44.600629-0500: icom_get_freq: wrong frame len=0 2023-01-18T18:34:44.600684-0500: 1:icom.c(1732):icom_get_freq returning(-9) Command rejected by the rig 2023-01-18T18:34:44.600858-0500: 0:rig_get_freq: elapsed=4ms 2023-01-18T18:34:44.600916-0500: 0:rig.c(6076):rig_get_powerstat returning(-9) Command rejected by the rig 2023-01-18T18:34:44.600977-0500: rigctl_parse: rig_powerstat is not on = 0 2023-01-18T18:34:44.601034-0500: 0:rigctl_parse.c(2127):rigctl_get_freq entered 2023-01-18T18:34:44.601094-0500: rig_get_freq(1996) called vfo=currVFO 2023-01-18T18:34:44.601183-0500: vfo_fixup:(from rig_get_freq:2002) vfo=currVFO, vfo_curr=currVFO, split=0 2023-01-18T18:34:44.601236-0500: vfo_fixup: Leaving currVFO alone 2023-01-18T18:34:44.601287-0500: rig.c(2005) vfo=currVFO, curr_vfo=currVFO 2023-01-18T18:34:44.601457-0500: rig_get_freq: cache miss age=10000ms, cached_vfo=currVFO, asked_vfo=currVFO, use_cached_freq=0 2023-01-18T18:34:44.601512-0500: rig_get_freq(2092): vfo_opt=0, model=3073 2023-01-18T18:34:44.601560-0500: icom_get_freq called for currVFO, curr_vfo=currVFO 2023-01-18T18:34:44.601613-0500: icom_get_freq: using vfo=currVFO 2023-01-18T18:34:44.601665-0500: 1:frame.c(425):icom_transaction entered 2023-01-18T18:34:44.601715-0500: icom_transaction: cmd=0x25, subcmd=0x00, payload_len=0 2023-01-18T18:34:44.601769-0500: 2:frame.c(138):icom_one_transaction entered 2023-01-18T18:34:44.601821-0500: rig_flush: called for serial device 2023-01-18T18:34:44.601870-0500: read_string_generic called, rxmax=4095 direct=1, expected_len=1 2023-01-18T18:34:44.603342-0500: 0000 fe fe e0 94 25 00 00 40 07 14 00 fd ....%..@.... 2023-01-18T18:34:44.603448-0500: write_block(): TX 7 bytes, method=2 2023-01-18T18:34:44.603508-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:44.603561-0500: read_string_generic called, rxmax=200 direct=1, expected_len=1 2023-01-18T18:34:44.604842-0500: read_string_generic(): RX 7 characters, direct=1 2023-01-18T18:34:44.604916-0500: 0000 fe fe 94 e0 25 00 fd ....%.. 2023-01-18T18:34:44.604974-0500: icom_one_transaction: frm_len=7, frm_len-1=fd, frm_len-2=00 2023-01-18T18:34:44.605035-0500: 2:frame.c(403):icom_one_transaction returning(0) 2023-01-18T18:34:44.605094-0500: 1:frame.c(455):icom_transaction returning(0) 2023-01-18T18:34:44.605150-0500: icom_get_freq: wrong frame len=0 2023-01-18T18:34:44.605207-0500: 0:icom.c(1732):icom_get_freq returning(-9) Command rejected by the rig 2023-01-18T18:34:44.605397-0500: -1:rig_get_freq: elapsed=4ms 2023-01-18T18:34:44.605470-0500: -1:rigctl_parse.c(2133):rigctl_get_freq returning(-9) Command rejected by the rig get_freq: error = write_block(): TX 7 bytes, method=2 0000 fe fe 94 e0 25 00 fd ....%.. read_string_generic called, rxmax=200 direct=1, expected_len=1 read_string_generic(): RX 7 characters, direct=1 0000 fe fe 94 e0 25 00 fd ....%.. icom_one_transaction: frm_len=7, frm_len-1=fd, frm_len-2=00 2:frame.c(403):icom_one_transaction returning(0) 1:frame.c(455):icom_transaction returning(0) icom_get_freq: wrong frame len=0 0:icom.c(1732):icom_get_freq returning(-9) Command rejected by the rig rig_get_freq(2109): freqMainA=0, modeMainA=, widthMainA=0 rig_get_freq(2109): freqMainB=0, modeMainB=, widthMainB=0 rig_get_cache(259): vfo=currVFO, current_vfo=currVFO rig_get_cache(435): vfo=VFOA, freq=0, mode=, width=0 rig_set_cache_freq(122): vfo=currVFO, current_vfo=currVFO Command rejected by the rig 2023-01-18T18:34:44.605847-0500: rigctl_parse: called, interactive=1 Rig command: From: Black Michael [mailto:mdblack98@yahoo.com] Try the latest please -- cleaned up things a bit and seems better behaved here and simpler. Mike W9MDB On Tuesday, January 17, 2023 at 04:26:58 PM CST, Howard Nurse <hlnurse@cmmsft.com> wrote: Mike, did I miss your latest response on the powerstat issue for the 7300? --Howard |
|
Try again please
Mike W9MDB
Message ID: ***@***.***>
|
When power is commanded OFF with set_powerstat 0 nothing special happens.
But when power is again commanded ON with set_powerstat 1 something weird happens.
Effect is same if USB plug is plugged to PC.
I assume IC7300 powers it USB circuits via USB cable from PC when powered OFF. That way it manages to keep the ci-v system alive waiting for possible set_power_on command.
When it finally arrives powering of USB circuit is moved from PC via USB cable to rig's own power.
(Or then just internal reset is done always for USB circuits when powered ON)
That causes small glitch that resets USB serial port and PC detects it like new USB device has been connected:
Jan 7 16:48:23 hamtpad kernel: usb 2-1.2.3: new low-speed USB device number 18 using ehci-pci
Jan 7 16:48:23 hamtpad kernel: usb 2-1.2.3: device descriptor read/64, error -32
Jan 7 16:48:23 hamtpad kernel: cp210x ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
Jan 7 16:48:23 hamtpad kernel: usb 2-1.2.3: device descriptor read/64, error -32
Jan 7 16:48:24 hamtpad kernel: usb 2-1.2.3: new low-speed USB device number 19 using ehci-pci
Jan 7 16:48:24 hamtpad kernel: cp210x ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
Jan 7 16:48:24 hamtpad kernel: usb 2-1.2.3: device descriptor read/64, error -32
Jan 7 16:48:24 hamtpad kernel: usb 2-1.2.3: device descriptor read/64, error -32
Jan 7 16:48:24 hamtpad kernel: usb 2-1.2-port3: attempt power cycle
Jan 7 16:48:24 hamtpad kernel: usb 2-1.2.3: new low-speed USB device number 20 using ehci-pci
Jan 7 16:48:25 hamtpad kernel: usb 2-1.2.3: device not accepting address 20, error -32
Jan 7 16:48:25 hamtpad kernel: usb 2-1.2.3: new low-speed USB device number 21 using ehci-pci
Jan 7 16:48:25 hamtpad kernel: usb 2-1.2.3: device not accepting address 21, error -32
Jan 7 16:48:25 hamtpad kernel: usb 2-1.2-port3: unable to enumerate USB device
The text was updated successfully, but these errors were encountered: