Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

IC-756 get_split_freq_mode fails #615

Closed
mdblack98 opened this issue Mar 17, 2021 · 3 comments
Closed

IC-756 get_split_freq_mode fails #615

mdblack98 opened this issue Mar 17, 2021 · 3 comments
Labels
bug critical A problem for common operations with WSJT-X, GPredict, RigPi, etc. JTDX Bugs affecting JTDX operations needs test Patches have been submitted but need testing to close issue WSJTX Bugs affecting WSTJ-X operations

Comments

@mdblack98
Copy link
Contributor

Ran for two hours but then failed -- end of log makes no sense as it appears actual rig functions were never called.

[2021-03-17 15:04:43.971186][03:18:55.659847][RIGCTRL:debug] icom_get_split_freq curr_vfo=Main
[2021-03-17 15:04:43.971186][03:18:55.659863][RIGCTRL:debug] icom_get_split_vfos called
[2021-03-17 15:04:43.971186][03:18:55.659885][RIGCTRL:trace] icom_get_split_vfos: VFO_HAS_MAIN_SUB_ONLY, split=0, rx=Main, tx=Main
[2021-03-17 15:04:43.971186][03:18:55.659903][RIGCTRL:debug] icom.c(4033):icom_get_split_vfos return(0)
[2021-03-17 15:04:43.971186][03:18:55.659919][RIGCTRL:debug] rig.c(2420):rig_set_vfo entered
[2021-03-17 15:04:43.971186][03:18:55.659934][RIGCTRL:debug] rig_set_vfo called vfo=Main
[2021-03-17 15:04:43.971186][03:18:55.659948][RIGCTRL:trace] vfo_fixup: vfo=Main
[2021-03-17 15:04:43.971186][03:18:55.659962][RIGCTRL:trace] vfo_fixup: final vfo=Main
[2021-03-17 15:04:43.971186][03:18:55.659977][RIGCTRL:debug] icom_set_vfo called vfo=Main
[2021-03-17 15:04:43.971186][03:18:55.659992][RIGCTRL:trace] icom_set_vfo: debug#2
[2021-03-17 15:04:43.971186][03:18:55.660006][RIGCTRL:trace] icom_set_vfo: debug#3
[2021-03-17 15:04:43.971186][03:18:55.660021][RIGCTRL:debug] frame.c(325):icom_transaction entered
[2021-03-17 15:04:43.971186][03:18:55.660041][RIGCTRL:debug] icom_transaction: cmd=0x07, subcmd=0xd0, payload_len=0
[2021-03-17 15:04:43.971186][03:18:55.660058][RIGCTRL:debug] frame.c(119):icom_one_transaction entered
[2021-03-17 15:04:43.971186][03:18:55.660075][RIGCTRL:debug] frame.c(56):make_cmd_frame entered
[2021-03-17 15:04:43.971186][03:18:55.660093][RIGCTRL:debug] frame.c(90):make_cmd_frame return(7)
[2021-03-17 15:04:43.971186][03:18:55.660110][RIGCTRL:trace] rig_flush: called for serial device
[2021-03-17 15:04:43.971186][03:18:55.660130][RIGCTRL:debug] serial.c(629):serial_flush entered
[2021-03-17 15:04:43.971186][03:18:55.660146][RIGCTRL:debug] tcflush
[2021-03-17 15:04:43.971186][03:18:55.660193][RIGCTRL:debug] serial.c(661):serial_flush return(0)
[2021-03-17 15:04:43.971186][03:18:55.660211][RIGCTRL:debug] write_block called
[2021-03-17 15:04:43.971186][03:18:55.660341][RIGCTRL:trace] write_block(): TX 7 bytes
[2021-03-17 15:04:43.971186][03:18:55.660364][RIGCTRL:trace] 0000 fe fe 50 e0 07 d0 fd ..P....
[2021-03-17 15:04:43.971186][03:18:55.660385][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-17 15:04:43.971186][03:18:55.660402][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-17 15:04:43.992950][03:18:55.681786][RIGCTRL:trace] read_string(): RX 7 characters
[2021-03-17 15:04:43.992950][03:18:55.681829][RIGCTRL:trace] 0000 fe fe 50 e0 07 d0 fd ..P....
[2021-03-17 15:04:43.992950][03:18:55.681852][RIGCTRL:debug] frame.c(409):read_icom_frame return(7)
[2021-03-17 15:04:43.992950][03:18:55.681871][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-17 15:04:43.992950][03:18:55.681893][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-17 15:04:44.004207][03:18:55.692990][RIGCTRL:trace] read_string(): RX 6 characters
[2021-03-17 15:04:44.004207][03:18:55.693030][RIGCTRL:trace] 0000 fe fe e0 50 fb fd ...P..
[2021-03-17 15:04:44.004207][03:18:55.693052][RIGCTRL:debug] frame.c(409):read_icom_frame return(6)
[2021-03-17 15:04:44.004207][03:18:55.693074][RIGCTRL:trace] icom_one_transaction: frm_len=6, frm_len-1=fd, frm_len-2=fb
[2021-03-17 15:04:44.004207][03:18:55.693094][RIGCTRL:debug] frame.c(303):icom_one_transaction return(0)
[2021-03-17 15:04:44.004207][03:18:55.693111][RIGCTRL:debug] frame.c(355):icom_transaction return(0)
[2021-03-17 15:04:44.004207][03:18:55.693127][RIGCTRL:trace] icom_set_vfo: debug#4
[2021-03-17 15:04:44.004207][03:18:55.693143][RIGCTRL:trace] icom_set_vfo: debug#5 curr_vfo=Main
[2021-03-17 15:04:44.004207][03:18:55.693163][RIGCTRL:debug] icom.c(2307):icom_set_vfo return(0)
[2021-03-17 15:04:44.004207][03:18:55.693181][RIGCTRL:trace] rig_set_vfo: rig->state.current_vfo=Main
[2021-03-17 15:04:44.004207][03:18:55.693198][RIGCTRL:debug] icom_get_freq called for Main, curr_vfo=Main
[2021-03-17 15:04:44.004207][03:18:55.693215][RIGCTRL:trace] set_vfo_curr: vfo=Main, curr_vfo=Main
[2021-03-17 15:04:44.004207][03:18:55.693232][RIGCTRL:trace] set_vfo_curr: curr_vfo now=Main
[2021-03-17 15:04:44.004207][03:18:55.693249][RIGCTRL:debug] icom.c(7675):set_vfo_curr return(0)
[2021-03-17 15:04:44.004207][03:18:55.693266][RIGCTRL:debug] icom_get_freq: using vfo=Main
[2021-03-17 15:04:44.004207][03:18:55.693284][RIGCTRL:debug] frame.c(325):icom_transaction entered
[2021-03-17 15:04:44.004207][03:18:55.693306][RIGCTRL:debug] icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0
[2021-03-17 15:04:44.004207][03:18:55.693323][RIGCTRL:debug] frame.c(119):icom_one_transaction entered
[2021-03-17 15:04:44.004207][03:18:55.693340][RIGCTRL:debug] frame.c(56):make_cmd_frame entered
[2021-03-17 15:04:44.004207][03:18:55.693359][RIGCTRL:debug] frame.c(90):make_cmd_frame return(6)
[2021-03-17 15:04:44.004207][03:18:55.693376][RIGCTRL:trace] rig_flush: called for serial device
[2021-03-17 15:04:44.004207][03:18:55.693394][RIGCTRL:debug] serial.c(629):serial_flush entered
[2021-03-17 15:04:44.004207][03:18:55.693410][RIGCTRL:debug] tcflush
[2021-03-17 15:04:44.004958][03:18:55.693454][RIGCTRL:debug] serial.c(661):serial_flush return(0)
[2021-03-17 15:04:44.004958][03:18:55.693471][RIGCTRL:debug] write_block called
[2021-03-17 15:04:44.004958][03:18:55.693589][RIGCTRL:trace] write_block(): TX 6 bytes
[2021-03-17 15:04:44.004958][03:18:55.693614][RIGCTRL:trace] 0000 fe fe 50 e0 03 fd ..P...
[2021-03-17 15:04:44.004958][03:18:55.693633][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-17 15:04:44.004958][03:18:55.693653][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-17 15:04:44.015466][03:18:55.704272][RIGCTRL:trace] read_string(): RX 6 characters
[2021-03-17 15:04:44.015466][03:18:55.704317][RIGCTRL:trace] 0000 fe fe 50 e0 03 fd ..P...
[2021-03-17 15:04:44.015466][03:18:55.704349][RIGCTRL:debug] frame.c(409):read_icom_frame return(6)
[2021-03-17 15:04:44.015466][03:18:55.704373][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-17 15:04:44.015466][03:18:55.704398][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-17 15:04:44.037230][03:18:55.726236][RIGCTRL:trace] read_string(): RX 11 characters
[2021-03-17 15:04:44.037230][03:18:55.726285][RIGCTRL:trace] 0000 fe fe e0 50 03 00 40 07 21 00 fd ...P..@.!..
[2021-03-17 15:04:44.037230][03:18:55.726309][RIGCTRL:debug] frame.c(409):read_icom_frame return(11)
[2021-03-17 15:04:44.037230][03:18:55.726335][RIGCTRL:trace] icom_one_transaction: frm_len=11, frm_len-1=fd, frm_len-2=00
[2021-03-17 15:04:44.037230][03:18:55.726356][RIGCTRL:debug] frame.c(303):icom_one_transaction return(0)
[2021-03-17 15:04:44.037230][03:18:55.726377][RIGCTRL:debug] frame.c(355):icom_transaction return(0)
[2021-03-17 15:04:44.037230][03:18:55.726398][RIGCTRL:debug] from_bcd called
[2021-03-17 15:04:44.037230][03:18:55.726419][RIGCTRL:debug] icom_get_freq exit vfo=Main, curr_vfo=Main
[2021-03-17 15:04:44.037980][03:18:55.726444][RIGCTRL:debug] icom.c(1339):icom_get_freq return(0)
[2021-03-17 15:04:44.037980][03:18:55.726477][RIGCTRL:trace] rig_set_vfo: retcode from rig_get_freq = Command completed successfully
icom_get_freq exit vfo=Main, curr_vfo=Main
icom.c(1339):icom_get_freq return(0)
rig_set_vfo: retcode from rig_get_freq = Command completed successfully
icom_get_freq exit vfo=Main, curr_vfo=Main
icom.c(1339):icom_get_freq return(0)
icom.c(1339):icom_get_freq return(0)
[2021-03-17 15:04:44.037980][03:18:55.726501][RIGCTRL:trace] rig_set_vfo: return 0, vfo=Main
[2021-03-17 15:04:44.037980][03:18:55.726523][RIGCTRL:debug] rig.c(2503):rig_set_vfo return(0)
[2021-03-17 15:04:44.037980][03:18:55.726544][RIGCTRL:debug] rig_get_freq called vfo=Main
[2021-03-17 15:04:44.037980][03:18:55.726562][RIGCTRL:trace] vfo_fixup: vfo=Main
[2021-03-17 15:04:44.037980][03:18:55.726580][RIGCTRL:trace] vfo_fixup: final vfo=Main
[2021-03-17 15:04:44.037980][03:18:55.726600][RIGCTRL:debug] rig.c(1489):rig_get_cache entered
[2021-03-17 15:04:44.037980][03:18:55.726620][RIGCTRL:trace] rig_get_cache: vfo=Main, current_vfo=Main
[2021-03-17 15:04:44.037980][03:18:55.726650][RIGCTRL:trace] rig_get_cache: vfo=Main, freq=21074000
[2021-03-17 15:04:44.037980][03:18:55.726670][RIGCTRL:debug] rig.c(1595):rig_get_cache return(0)
[2021-03-17 15:04:44.037980][03:18:55.726690][RIGCTRL:trace] rig_get_freq: cache check1 age=658ms
[2021-03-17 15:04:44.037980][03:18:55.726713][RIGCTRL:trace] rig_get_freq: cache miss age=658ms, cached_vfo=Main, asked_vfo=Main
[2021-03-17 15:04:44.037980][03:18:55.726733][RIGCTRL:debug] icom_get_freq called for Main, curr_vfo=Main
[2021-03-17 15:04:44.037980][03:18:55.726752][RIGCTRL:trace] set_vfo_curr: vfo=Main, curr_vfo=Main
[2021-03-17 15:04:44.037980][03:18:55.726772][RIGCTRL:trace] set_vfo_curr: curr_vfo now=Main
[2021-03-17 15:04:44.037980][03:18:55.726792][RIGCTRL:debug] icom.c(7675):set_vfo_curr return(0)
[2021-03-17 15:04:44.037980][03:18:55.726812][RIGCTRL:debug] icom_get_freq: using vfo=Main
[2021-03-17 15:04:44.037980][03:18:55.726832][RIGCTRL:debug] frame.c(325):icom_transaction entered
[2021-03-17 15:04:44.037980][03:18:55.726857][RIGCTRL:debug] icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0
[2021-03-17 15:04:44.037980][03:18:55.726877][RIGCTRL:debug] frame.c(119):icom_one_transaction entered
[2021-03-17 15:04:44.037980][03:18:55.726896][RIGCTRL:debug] frame.c(56):make_cmd_frame entered
[2021-03-17 15:04:44.037980][03:18:55.726917][RIGCTRL:debug] frame.c(90):make_cmd_frame return(6)
[2021-03-17 15:04:44.037980][03:18:55.726937][RIGCTRL:trace] rig_flush: called for serial device
[2021-03-17 15:04:44.037980][03:18:55.726957][RIGCTRL:debug] serial.c(629):serial_flush entered
[2021-03-17 15:04:44.037980][03:18:55.726975][RIGCTRL:debug] tcflush
[2021-03-17 15:04:44.037980][03:18:55.727022][RIGCTRL:debug] serial.c(661):serial_flush return(0)
[2021-03-17 15:04:44.037980][03:18:55.727041][RIGCTRL:debug] write_block called
[2021-03-17 15:04:44.037980][03:18:55.727157][RIGCTRL:trace] write_block(): TX 6 bytes
[2021-03-17 15:04:44.038731][03:18:55.727183][RIGCTRL:trace] 0000 fe fe 50 e0 03 fd ..P...
[2021-03-17 15:04:44.038731][03:18:55.727206][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-17 15:04:44.038731][03:18:55.727227][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-17 15:04:44.091266][03:18:55.780081][RIGCTRL:trace] read_string(): RX 6 characters
[2021-03-17 15:04:44.091266][03:18:55.780133][RIGCTRL:trace] 0000 fe fe 50 e0 03 fd ..P...
[2021-03-17 15:04:44.091266][03:18:55.780163][RIGCTRL:debug] frame.c(409):read_icom_frame return(6)
[2021-03-17 15:04:44.091266][03:18:55.780186][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-17 15:04:44.091266][03:18:55.780206][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-17 15:04:44.102523][03:18:55.791502][RIGCTRL:trace] read_string(): RX 11 characters
[2021-03-17 15:04:44.102523][03:18:55.791549][RIGCTRL:trace] 0000 fe fe e0 50 03 00 40 07 21 00 fd ...P..@.!..
[2021-03-17 15:04:44.102523][03:18:55.791574][RIGCTRL:debug] frame.c(409):read_icom_frame return(11)
[2021-03-17 15:04:44.102523][03:18:55.791604][RIGCTRL:trace] icom_one_transaction: frm_len=11, frm_len-1=fd, frm_len-2=00
[2021-03-17 15:04:44.102523][03:18:55.791625][RIGCTRL:debug] frame.c(303):icom_one_transaction return(0)
[2021-03-17 15:04:44.102523][03:18:55.791646][RIGCTRL:debug] frame.c(355):icom_transaction return(0)
[2021-03-17 15:04:44.102523][03:18:55.791664][RIGCTRL:debug] from_bcd called
[2021-03-17 15:04:44.102523][03:18:55.791685][RIGCTRL:debug] icom_get_freq exit vfo=Main, curr_vfo=Main
[2021-03-17 15:04:44.103274][03:18:55.791707][RIGCTRL:debug] icom.c(1339):icom_get_freq return(0)
[2021-03-17 15:04:44.103274][03:18:55.791732][RIGCTRL:debug] rig.c(1397):set_cache_freq entered
[2021-03-17 15:04:44.103274][03:18:55.791755][RIGCTRL:trace] set_cache_freq: vfo=Main, current_vfo=Main
[2021-03-17 15:04:44.103274][03:18:55.791785][RIGCTRL:trace] set_cache_freq: set vfo=Main to freq=21074000
[2021-03-17 15:04:44.103274][03:18:55.791807][RIGCTRL:debug] rig.c(1483):set_cache_freq return(0)
[2021-03-17 15:04:44.103274][03:18:55.791828][RIGCTRL:debug] rig.c(1397):set_cache_freq entered
[2021-03-17 15:04:44.103274][03:18:55.791849][RIGCTRL:trace] set_cache_freq: vfo=Main, current_vfo=Main
[2021-03-17 15:04:44.103274][03:18:55.791873][RIGCTRL:trace] set_cache_freq: set vfo=Main to freq=21074000
[2021-03-17 15:04:44.103274][03:18:55.791894][RIGCTRL:debug] rig.c(1483):set_cache_freq return(0)
[2021-03-17 15:04:44.103274][03:18:55.791916][RIGCTRL:debug] rig.c(2017):rig_get_freq return(0)
[2021-03-17 15:04:44.103274][03:18:55.791939][RIGCTRL:debug] rig.c(2420):rig_set_vfo entered
[2021-03-17 15:04:44.103274][03:18:55.791962][RIGCTRL:debug] rig_set_vfo called vfo=Main
[2021-03-17 15:04:44.103274][03:18:55.791982][RIGCTRL:trace] vfo_fixup: vfo=Main
[2021-03-17 15:04:44.103274][03:18:55.792000][RIGCTRL:trace] vfo_fixup: final vfo=Main
[2021-03-17 15:04:44.103274][03:18:55.792018][RIGCTRL:debug] icom_set_vfo called vfo=Main
[2021-03-17 15:04:44.103274][03:18:55.792035][RIGCTRL:trace] icom_set_vfo: debug#2
[2021-03-17 15:04:44.103274][03:18:55.792052][RIGCTRL:trace] icom_set_vfo: debug#3
[2021-03-17 15:04:44.103274][03:18:55.792071][RIGCTRL:debug] frame.c(325):icom_transaction entered
[2021-03-17 15:04:44.103274][03:18:55.792095][RIGCTRL:debug] icom_transaction: cmd=0x07, subcmd=0xd0, payload_len=0
[2021-03-17 15:04:44.103274][03:18:55.792115][RIGCTRL:debug] frame.c(119):icom_one_transaction entered
[2021-03-17 15:04:44.103274][03:18:55.792134][RIGCTRL:debug] frame.c(56):make_cmd_frame entered
[2021-03-17 15:04:44.103274][03:18:55.792155][RIGCTRL:debug] frame.c(90):make_cmd_frame return(7)
[2021-03-17 15:04:44.103274][03:18:55.792178][RIGCTRL:trace] rig_flush: called for serial device
[2021-03-17 15:04:44.103274][03:18:55.792201][RIGCTRL:debug] serial.c(629):serial_flush entered
[2021-03-17 15:04:44.103274][03:18:55.792219][RIGCTRL:debug] tcflush
[2021-03-17 15:04:44.103274][03:18:55.792269][RIGCTRL:debug] serial.c(661):serial_flush return(0)
[2021-03-17 15:04:44.103274][03:18:55.792291][RIGCTRL:debug] write_block called
[2021-03-17 15:04:44.103274][03:18:55.792425][RIGCTRL:trace] write_block(): TX 7 bytes
[2021-03-17 15:04:44.104024][03:18:55.792454][RIGCTRL:trace] 0000 fe fe 50 e0 07 d0 fd ..P....
[2021-03-17 15:04:44.104024][03:18:55.792477][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-17 15:04:44.104024][03:18:55.792500][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-17 15:04:44.114531][03:18:55.803310][RIGCTRL:trace] read_string(): RX 7 characters
[2021-03-17 15:04:44.114531][03:18:55.803354][RIGCTRL:trace] 0000 fe fe 50 e0 07 d0 fd ..P....
[2021-03-17 15:04:44.114531][03:18:55.803379][RIGCTRL:debug] frame.c(409):read_icom_frame return(7)
[2021-03-17 15:04:44.114531][03:18:55.803400][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-17 15:04:44.114531][03:18:55.803421][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-17 15:04:44.136296][03:18:55.825051][RIGCTRL:trace] read_string(): RX 6 characters
[2021-03-17 15:04:44.136296][03:18:55.825097][RIGCTRL:trace] 0000 fe fe e0 50 fb fd ...P..
[2021-03-17 15:04:44.136296][03:18:55.825125][RIGCTRL:debug] frame.c(409):read_icom_frame return(6)
[2021-03-17 15:04:44.136296][03:18:55.825154][RIGCTRL:trace] icom_one_transaction: frm_len=6, frm_len-1=fd, frm_len-2=fb
[2021-03-17 15:04:44.136296][03:18:55.825178][RIGCTRL:debug] frame.c(303):icom_one_transaction return(0)
[2021-03-17 15:04:44.136296][03:18:55.825199][RIGCTRL:debug] frame.c(355):icom_transaction return(0)
[2021-03-17 15:04:44.136296][03:18:55.825219][RIGCTRL:trace] icom_set_vfo: debug#4
[2021-03-17 15:04:44.136296][03:18:55.825241][RIGCTRL:trace] icom_set_vfo: debug#5 curr_vfo=Main
[2021-03-17 15:04:44.136296][03:18:55.825267][RIGCTRL:debug] icom.c(2307):icom_set_vfo return(0)
[2021-03-17 15:04:44.136296][03:18:55.825290][RIGCTRL:trace] rig_set_vfo: rig->state.current_vfo=Main
[2021-03-17 15:04:44.136296][03:18:55.825312][RIGCTRL:debug] icom_get_freq called for Main, curr_vfo=Main
[2021-03-17 15:04:44.136296][03:18:55.825332][RIGCTRL:trace] set_vfo_curr: vfo=Main, curr_vfo=Main
[2021-03-17 15:04:44.136296][03:18:55.825353][RIGCTRL:trace] set_vfo_curr: curr_vfo now=Main
[2021-03-17 15:04:44.136296][03:18:55.825373][RIGCTRL:debug] icom.c(7675):set_vfo_curr return(0)
[2021-03-17 15:04:44.136296][03:18:55.825394][RIGCTRL:debug] icom_get_freq: using vfo=Main
[2021-03-17 15:04:44.136296][03:18:55.825414][RIGCTRL:debug] frame.c(325):icom_transaction entered
[2021-03-17 15:04:44.136296][03:18:55.825439][RIGCTRL:debug] icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0
[2021-03-17 15:04:44.137047][03:18:55.825462][RIGCTRL:debug] frame.c(119):icom_one_transaction entered
[2021-03-17 15:04:44.137047][03:18:55.825481][RIGCTRL:debug] frame.c(56):make_cmd_frame entered
[2021-03-17 15:04:44.137047][03:18:55.825502][RIGCTRL:debug] frame.c(90):make_cmd_frame return(6)
[2021-03-17 15:04:44.137047][03:18:55.825522][RIGCTRL:trace] rig_flush: called for serial device
[2021-03-17 15:04:44.137047][03:18:55.825543][RIGCTRL:debug] serial.c(629):serial_flush entered
[2021-03-17 15:04:44.137047][03:18:55.825560][RIGCTRL:debug] tcflush
[2021-03-17 15:04:44.137047][03:18:55.825606][RIGCTRL:debug] serial.c(661):serial_flush return(0)
[2021-03-17 15:04:44.137047][03:18:55.825628][RIGCTRL:debug] write_block called
[2021-03-17 15:04:44.137047][03:18:55.825742][RIGCTRL:trace] write_block(): TX 6 bytes
[2021-03-17 15:04:44.137047][03:18:55.825770][RIGCTRL:trace] 0000 fe fe 50 e0 03 fd ..P...
[2021-03-17 15:04:44.137047][03:18:55.825793][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-17 15:04:44.137047][03:18:55.825813][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-17 15:04:44.179074][03:18:55.867826][RIGCTRL:trace] read_string(): RX 6 characters
[2021-03-17 15:04:44.179074][03:18:55.867872][RIGCTRL:trace] 0000 fe fe 50 e0 03 fd ..P...
[2021-03-17 15:04:44.179074][03:18:55.867897][RIGCTRL:debug] frame.c(409):read_icom_frame return(6)
[2021-03-17 15:04:44.179074][03:18:55.867917][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-17 15:04:44.179074][03:18:55.867937][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-17 15:04:44.200839][03:18:55.889768][RIGCTRL:trace] read_string(): RX 11 characters
[2021-03-17 15:04:44.200839][03:18:55.889818][RIGCTRL:trace] 0000 fe fe e0 50 03 00 40 07 21 00 fd ...P..@.!..
[2021-03-17 15:04:44.200839][03:18:55.889846][RIGCTRL:debug] frame.c(409):read_icom_frame return(11)
[2021-03-17 15:04:44.200839][03:18:55.889870][RIGCTRL:trace] icom_one_transaction: frm_len=11, frm_len-1=fd, frm_len-2=00
[2021-03-17 15:04:44.200839][03:18:55.889884][RIGCTRL:debug] frame.c(303):icom_one_transaction return(0)
[2021-03-17 15:04:44.200839][03:18:55.889895][RIGCTRL:debug] frame.c(355):icom_transaction return(0)
[2021-03-17 15:04:44.200839][03:18:55.889906][RIGCTRL:debug] from_bcd called
[2021-03-17 15:04:44.200839][03:18:55.889917][RIGCTRL:debug] icom_get_freq exit vfo=Main, curr_vfo=Main
[2021-03-17 15:04:44.200839][03:18:55.889930][RIGCTRL:debug] icom.c(1339):icom_get_freq return(0)
[2021-03-17 15:04:44.200839][03:18:55.889952][RIGCTRL:trace] rig_set_vfo: retcode from rig_get_freq = Command completed successfully
icom_get_freq exit vfo=Main, curr_vfo=Main
icom.c(1339):icom_get_freq return(0)
rig_set_vfo: retcode from rig_get_freq = Command completed successfully
icom_get_freq exit vfo=Main, curr_vfo=Main
icom.c(1339):icom_get_freq return(0)
icom.c(1339):icom_get_freq return(0)
[2021-03-17 15:04:44.200839][03:18:55.889965][RIGCTRL:trace] rig_set_vfo: return 0, vfo=Main
[2021-03-17 15:04:44.201589][03:18:55.889984][RIGCTRL:debug] rig.c(2503):rig_set_vfo return(0)
[2021-03-17 15:04:44.201589][03:18:55.890004][RIGCTRL:debug] icom.c(4454):icom_get_split_freq return(0)
[2021-03-17 15:04:44.201589][03:18:55.890016][RIGCTRL:debug] rig.c(3595):rig_get_split_freq return(0)
[2021-03-17 15:04:44.201589][03:18:55.890045][RIGCTRL:error] rig_set_split_freq_mode: txfreq!=tfreq 21073000!=21074000, retry=0, rc1=0, rc2=0
[2021-03-17 15:04:44.251873][03:18:55.940323][RIGCTRL:debug] rig.c(3974):rig_set_split_freq_mode return(-8)
[2021-03-17 15:04:44.251873][03:18:55.940357][RIGCTRL:error] error: Protocol error
rig.c(3595):rig_get_split_freq return(0)
rig_set_split_freq_mode: txfreq!=tfreq 21073000!=21074000, retry=0, rc1=0, rc2=0
rig.c(3974):rig_set_split_freq_mode return(-8)
[2021-03-17 15:04:44.251873][03:18:55.940503][RIGCTRL:trace] PTT: false Transceiver::TransceiverState(online: yes Frequency {21074000Hz, 0Hz} Mode: 3; SPLIT: off; PTT: off) reversed=false
[2021-03-17 15:04:44.251873][03:18:55.940529][RIGCTRL:trace] rig_set_ptt PTT=false
[2021-03-17 15:04:44.251873][03:18:55.940559][RIGCTRL:debug] rig.c(2602):rig_set_ptt entered
[2021-03-17 15:04:44.251873][03:18:55.940585][RIGCTRL:debug] serial.c(833):ser_set_rts entered
[2021-03-17 15:04:44.251873][03:18:55.940611][RIGCTRL:debug] ser_set_rts: RTS=0
[2021-03-17 15:04:44.251873][03:18:55.940662][RIGCTRL:debug] serial.c(873):ser_set_rts return(0)
[2021-03-17 15:04:44.251873][03:18:55.940691][RIGCTRL:debug] rig.c(2819):rig_set_ptt return(0)
[2021-03-17 15:04:44.251873][03:18:55.940719][RIGCTRL:debug] rig.c(1071):rig_close entered
[2021-03-17 15:04:44.251873][03:18:55.940742][RIGCTRL:trace] icom_rig_close: called
[2021-03-17 15:04:44.251873][03:18:55.940767][RIGCTRL:debug] icom.c(863):icom_rig_close return(0)
[2021-03-17 15:04:44.251873][03:18:55.940794][RIGCTRL:debug] serial.c(833):ser_set_rts entered
[2021-03-17 15:04:44.251873][03:18:55.940816][RIGCTRL:debug] ser_set_rts: RTS=0
[2021-03-17 15:04:44.251873][03:18:55.940858][RIGCTRL:debug] serial.c(873):ser_set_rts return(0)
[2021-03-17 15:04:44.251873][03:18:55.940880][RIGCTRL:debug] port_close called
[2021-03-17 15:04:44.251873][03:18:55.940897][RIGCTRL:debug] ser_close called
[2021-03-17 15:04:44.251873][03:18:55.940914][RIGCTRL:debug] ser_close: restoring options
[2021-03-17 15:04:44.260128][03:18:55.948675][SYSLOG:error] handle_transceiver_failure: reason: Hamlib error: Protocol error
rig.c(3595):rig_get_split_freq return(0)
rig_set_split_freq_mode: txfreq!=tfreq 21073000!=21074000, retry=0, rc1=0, rc2=0
rig.c(3974):rig_set_split_freq_mode return(-8) while setting split TX frequency and mode
@mdblack98
Copy link
Contributor Author

RETURNFUNC contains function call...perhaps causing some problem on the stack?
Will change all RETURNFUNC calls to remove function calls to a separate line.

@mdblack98 mdblack98 added bug critical A problem for common operations with WSJT-X, GPredict, RigPi, etc. JTDX Bugs affecting JTDX operations WSJTX Bugs affecting WSTJ-X operations labels Mar 17, 2021
@mdblack98
Copy link
Contributor Author

Turns out this error occurred on band change.

mdblack98 added a commit that referenced this issue Mar 18, 2021
@mdblack98
In rig.c change RETURNFUNC calls with functions into separate lines
c7c5cd8 
#615
@mdblack98 mdblack98 added the needs test Patches have been submitted but need testing to close issue label Mar 18, 2021
mdblack98 added a commit that referenced this issue Mar 18, 2021
@mdblack98
Remove all frequency verification as it seems to create problems on s…
b9cc75c 
…ome rigs

#615
@mdblack98
Copy link
Contributor Author

Flush timing seems to fail so we don't end up flushing the freq request correctly.
We need to actually read it to allow for slow responses.
[2021-03-18 22:13:57.152750][00:00:01.869185][RIGCTRL:trace] starting: Icom: IC-756
[2021-03-18 22:13:57.152750][00:00:01.869278][RIGCTRL:debug] rig.c(654):rig_open entered
[2021-03-18 22:13:57.152750][00:00:01.869316][RIGCTRL:debug] port_open called
[2021-03-18 22:13:57.152750][00:00:01.869344][RIGCTRL:debug] serial.c(144):serial_open entered
[2021-03-18 22:13:57.152750][00:00:01.869364][RIGCTRL:debug] serial_open: COM5
[2021-03-18 22:13:57.152750][00:00:01.869587][RIGCTRL:debug] serial.c(278):serial_setup entered
[2021-03-18 22:13:57.152750][00:00:01.869611][RIGCTRL:trace] serial_setup: tcgetattr
[2021-03-18 22:13:57.152750][00:00:01.869658][RIGCTRL:trace] serial_setup: cfsetispeed=19200,0x000e
[2021-03-18 22:13:57.152750][00:00:01.869681][RIGCTRL:trace] serial_setup: cfsetospeed=19200,0x000e
[2021-03-18 22:13:57.152750][00:00:01.869701][RIGCTRL:trace] serial_setup: data_bits=8
[2021-03-18 22:13:57.152750][00:00:01.869721][RIGCTRL:trace] serial_setup: parity=0
[2021-03-18 22:13:57.152750][00:00:01.869768][RIGCTRL:trace] serial_setup: tcsetattr TCSANOW
[2021-03-18 22:13:57.152750][00:00:01.869850][RIGCTRL:debug] serial.c(618):serial_setup return(0)
[2021-03-18 22:13:57.152750][00:00:01.869871][RIGCTRL:debug] serial.c(629):serial_flush entered
[2021-03-18 22:13:57.153501][00:00:01.869889][RIGCTRL:debug] tcflush
[2021-03-18 22:13:57.153501][00:00:01.869932][RIGCTRL:debug] serial.c(661):serial_flush return(0)
[2021-03-18 22:13:57.203785][00:00:01.920216][RIGCTRL:debug] serial.c(253):serial_open return(0)
[2021-03-18 22:13:57.203785][00:00:01.920270][RIGCTRL:debug] serial.c(833):ser_set_rts entered
[2021-03-18 22:13:57.203785][00:00:01.920290][RIGCTRL:debug] ser_set_rts: RTS=0
[2021-03-18 22:13:57.203785][00:00:01.920341][RIGCTRL:debug] serial.c(873):ser_set_rts return(0)
[2021-03-18 22:13:57.203785][00:00:01.920363][RIGCTRL:debug] rig.c(214):add_opened_rig return(0)
[2021-03-18 22:13:57.203785][00:00:01.920392][RIGCTRL:debug] icom.c(758):icom_rig_open entered
[2021-03-18 22:13:57.203785][00:00:01.920415][RIGCTRL:debug] icom_rig_open: IC-756 v20210316.0
[2021-03-18 22:13:57.203785][00:00:01.920434][RIGCTRL:debug] icom_get_usb_echo_off called
[2021-03-18 22:13:57.203785][00:00:01.920452][RIGCTRL:debug] icom_get_usb_echo_off: retry temp set to 0
[2021-03-18 22:13:57.203785][00:00:01.920478][RIGCTRL:debug] frame.c(325):icom_transaction entered
[2021-03-18 22:13:57.203785][00:00:01.920505][RIGCTRL:debug] icom_transaction: cmd=0x03, subcmd=0xffffffff, payload_len=0
[2021-03-18 22:13:57.203785][00:00:01.920534][RIGCTRL:debug] frame.c(119):icom_one_transaction entered
[2021-03-18 22:13:57.203785][00:00:01.920560][RIGCTRL:debug] frame.c(56):make_cmd_frame entered
[2021-03-18 22:13:57.203785][00:00:01.920581][RIGCTRL:debug] frame.c(90):make_cmd_frame return(6)
[2021-03-18 22:13:57.203785][00:00:01.920601][RIGCTRL:trace] rig_flush: called for serial device
[2021-03-18 22:13:57.203785][00:00:01.920620][RIGCTRL:debug] serial.c(629):serial_flush entered
[2021-03-18 22:13:57.203785][00:00:01.920637][RIGCTRL:debug] tcflush
[2021-03-18 22:13:57.203785][00:00:01.920684][RIGCTRL:debug] serial.c(661):serial_flush return(0)
[2021-03-18 22:13:57.203785][00:00:01.920710][RIGCTRL:debug] write_block called
[2021-03-18 22:13:57.203785][00:00:01.920840][RIGCTRL:trace] write_block(): TX 6 bytes
[2021-03-18 22:13:57.203785][00:00:01.920880][RIGCTRL:trace] 0000 fe fe 50 e0 03 fd ..P...
[2021-03-18 22:13:57.204535][00:00:01.920915][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-18 22:13:57.204535][00:00:01.920942][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-18 22:13:57.215042][00:00:01.931822][RIGCTRL:trace] read_string(): RX 6 characters
[2021-03-18 22:13:57.215042][00:00:01.931900][RIGCTRL:trace] 0000 fe fe 50 e0 03 fd ..P...
[2021-03-18 22:13:57.215042][00:00:01.931932][RIGCTRL:debug] frame.c(409):read_icom_frame return(6)
[2021-03-18 22:13:57.215042][00:00:01.931961][RIGCTRL:trace] icom_one_transaction: frm_len=6, frm_len-1=fd, frm_len-2=03
[2021-03-18 22:13:57.215042][00:00:01.931985][RIGCTRL:debug] frame.c(303):icom_one_transaction return(0)
[2021-03-18 22:13:57.215042][00:00:01.932007][RIGCTRL:debug] frame.c(355):icom_transaction return(0)
[2021-03-18 22:13:57.215042][00:00:01.932027][RIGCTRL:debug] icom_get_usb_echo_off: ack_len=1
[2021-03-18 22:13:57.215042][00:00:01.932044][RIGCTRL:debug] icom_get_usb_echo_off: USB echo on detected
[2021-03-18 22:13:57.215042][00:00:01.932064][RIGCTRL:debug] icom.c(742):icom_get_usb_echo_off return(0)
[2021-03-18 22:13:57.215042][00:00:01.932099][RIGCTRL:debug] rig_get_freq called vfo=VFOA
[2021-03-18 22:13:57.215042][00:00:01.932126][RIGCTRL:trace] vfo_fixup: vfo=VFOA
[2021-03-18 22:13:57.215042][00:00:01.932148][RIGCTRL:trace] vfo_fixup: final vfo=VFOA
[2021-03-18 22:13:57.215793][00:00:01.932172][RIGCTRL:debug] rig.c(1489):rig_get_cache entered
[2021-03-18 22:13:57.215793][00:00:01.932194][RIGCTRL:trace] rig_get_cache: vfo=VFOA, current_vfo=None
[2021-03-18 22:13:57.215793][00:00:01.932243][RIGCTRL:trace] rig_get_cache: vfo=VFOA, freq=0
[2021-03-18 22:13:57.215793][00:00:01.932269][RIGCTRL:debug] rig.c(1595):rig_get_cache return(0)
[2021-03-18 22:13:57.215793][00:00:01.932289][RIGCTRL:trace] rig_get_freq: cache check1 age=1000000ms
[2021-03-18 22:13:57.215793][00:00:01.932311][RIGCTRL:trace] rig_get_freq: cache miss age=1000000ms, cached_vfo=VFOA, asked_vfo=VFOA
[2021-03-18 22:13:57.215793][00:00:01.932343][RIGCTRL:debug] icom_set_vfo called vfo=VFOA
[2021-03-18 22:13:57.215793][00:00:01.932369][RIGCTRL:error] icom_set_vfo: Rig does not have VFO A/B?
[2021-03-18 22:13:57.215793][00:00:01.932394][RIGCTRL:error] icom_set_vfo: Mapping VFOA=Main
[2021-03-18 22:13:57.215793][00:00:01.932416][RIGCTRL:trace] icom_set_vfo: VFO changing from None to Main
[2021-03-18 22:13:57.215793][00:00:01.932435][RIGCTRL:trace] icom_set_vfo: debug#2
[2021-03-18 22:13:57.215793][00:00:01.932454][RIGCTRL:trace] icom_set_vfo: debug#3
[2021-03-18 22:13:57.215793][00:00:01.932474][RIGCTRL:debug] frame.c(325):icom_transaction entered
[2021-03-18 22:13:57.215793][00:00:01.932497][RIGCTRL:debug] icom_transaction: cmd=0x07, subcmd=0xd0, payload_len=0
[2021-03-18 22:13:57.215793][00:00:01.932524][RIGCTRL:debug] frame.c(119):icom_one_transaction entered
[2021-03-18 22:13:57.215793][00:00:01.932544][RIGCTRL:debug] frame.c(56):make_cmd_frame entered
[2021-03-18 22:13:57.215793][00:00:01.932564][RIGCTRL:debug] frame.c(90):make_cmd_frame return(7)
[2021-03-18 22:13:57.215793][00:00:01.932584][RIGCTRL:trace] rig_flush: called for serial device
[2021-03-18 22:13:57.215793][00:00:01.932606][RIGCTRL:debug] serial.c(629):serial_flush entered
[2021-03-18 22:13:57.215793][00:00:01.932623][RIGCTRL:debug] tcflush
[2021-03-18 22:13:57.215793][00:00:01.932679][RIGCTRL:debug] serial.c(661):serial_flush return(0)
[2021-03-18 22:13:57.215793][00:00:01.932699][RIGCTRL:debug] write_block called
[2021-03-18 22:13:57.215793][00:00:01.932874][RIGCTRL:trace] write_block(): TX 7 bytes
[2021-03-18 22:13:57.216543][00:00:01.932906][RIGCTRL:trace] 0000 fe fe 50 e0 07 d0 fd ..P....
[2021-03-18 22:13:57.216543][00:00:01.932932][RIGCTRL:debug] frame.c(375):read_icom_frame entered
[2021-03-18 22:13:57.216543][00:00:01.932952][RIGCTRL:trace] read_string called, rxmax=80
[2021-03-18 22:13:57.237558][00:00:01.954497][RIGCTRL:trace] read_string(): RX 11 characters
[2021-03-18 22:13:57.237558][00:00:01.954552][RIGCTRL:trace] 0000 fe fe e0 50 03 00 40 07 14 00 fd ...P..@....
[2021-03-18 22:13:57.237558][00:00:01.954584][RIGCTRL:debug] frame.c(409):read_icom_frame return(11)
[2021-03-18 22:13:57.237558][00:00:01.954616][RIGCTRL:debug] frame.c(204):icom_one_transaction return(-8)
[2021-03-18 22:13:57.238308][00:00:01.954811][RIGCTRL:warning] icom_transaction: retry=3: Protocol error
frame.c(409):read_icom_frame return(11)
frame.c(204):icom_one_transaction return(-8)
icom_transaction: retry=3: Protocol error
frame.c(409):read_icom_frame return(11)
frame.c(204):icom_one_transaction return(-8)
frame.c(204):icom_one_transaction return(-8)
[2021-03-18 22:13:57.338875][00:00:02.055271][RIGCTRL:debug] frame.c(119):icom_one_transaction entered

mdblack98 added a commit that referenced this issue Mar 19, 2021
@mdblack98
Fix Icom icom_get_usb_echo_off to read the freq response when echo is on
c1277b1 
This takes into account whatever the response time of the rig is
#615
@mdblack98 mdblack98 added this to the 4.2 milestone Mar 19, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug critical A problem for common operations with WSJT-X, GPredict, RigPi, etc. JTDX Bugs affecting JTDX operations needs test Patches have been submitted but need testing to close issue WSJTX Bugs affecting WSTJ-X operations
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@mdblack98