OTP crash while changing menu 6-11 or 6-12

tonyc commented 2 years ago

The low/high bandscope edge frequencies seem to be missing. Where'd they go?

Tyrbiter commented 2 years ago

I see them in hi/lo-cut mode, the display switches when I change it in menu 6-11 in either direction.

And the bandscope edges are showing for me too ;-)

I'm using Firefox 102.

tonyc commented 2 years ago

I'm not sure what caused me to see this, but I'm actually getting them now that I've changed branches locally a couple times. On the radar, at least.

tonyc commented 2 years ago

There seems to be a crash+restart when switching from CW to SSB, and then adjusting menu 6-11 from High & Low Cut to Shift & Width:

[info] TIMER: Update cloudlog
[info] Pinging cloudlog: 14314730, :cw
[info] [DN] "OM02"
[info] [DN] "RL104"
[debug] Dispatch: unknown message: "RL104"
[info] [DN] "SH0022"
[info] [DN] "SH1022"
[debug] Dispatch: unknown message: "SH1022"
[info] [DN] "SL003"
[info] [DN] "SL103"
[debug] Dispatch: unknown message: "SL103"
[info] [DN] "TF12"
[debug] Dispatch: unknown message: "TF12"
[info] [DN] "TF24"
[debug] Dispatch: unknown message: "TF24"
[info] [DN] "BSA1"
[info] [DN] "EQT00"
[debug] Dispatch: unknown message: "EQT00"
[info] [DN] "EQT15"
[debug] Dispatch: unknown message: "EQT15"
[info] [DN] "FB00014314030"
[info] [DN] "FL1000270"
[info] [DN] "FL210"
[debug] Dispatch: unknown message: "FL210"
[info] [DN] "FL222"
[debug] Dispatch: unknown message: "FL222"
[info] [DN] "FL310"
[debug] Dispatch: unknown message: "FL310"
[info] [DN] "FL322"
[debug] Dispatch: unknown message: "FL322"
[info] [DN] "GT161105"
[debug] Dispatch: unknown message: "GT161105"
[debug] Cloudlog response: %{"status" => "success"}
[info] TIMER: Update cloudlog
[info] Pinging cloudlog: 14314030, :usb
[debug] Cloudlog response: %{"status" => "success"}
[info] [DN] "SH0029"
[error] GenServer {:radio_connection_registry, {:tcp, "903e7dd4-38b7-4466-b48a-6b95b144ae44"}} terminating
** (ArgumentError) argument error
    :erlang.element(30, {600, 700, 800, 900, 1000, 1100, 1200, 1300, 1400, 1500, 1600, 1700, 1800, 1900, 2000, 2100, 2200, 2300, 2400, 2500, 2600, 2700, 2800, 2900, 3000, 3400, 4000, 5000})
    (open890 0.1.0) lib/open890/extract.ex:546: Open890.Extract.get_ssb_hi_cut/1
    (open890 0.1.0) lib/open890/radio_state.ex:573: Open890.RadioState.dispatch/2
    (open890 0.1.0) lib/open890/tcp_client.ex:307: Open890.TCPClient.handle_msg/2
    (elixir 1.12.3) lib/enum.ex:2385: Enum."-reduce/3-lists^foldl/2-0-"/3
    (open890 0.1.0) lib/open890/tcp_client.ex:76: Open890.TCPClient.handle_info/2
    (stdlib 3.14.2.2) gen_server.erl:689: :gen_server.try_dispatch/4
    (stdlib 3.14.2.2) gen_server.erl:765: :gen_server.handle_msg/6
    (stdlib 3.14.2.2) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
Last message: {:tcp, #Port<0.27>, "SH0029;SH1029;"}
State: %{connection: #Open890.RadioConnection<auto_start: "true", cloudlog_api_key: "REDACTED", cloudlog_enabled: "true", cloudlog_url: "REDACTED", id: "903e7dd4-38b7-4466-b48a-6b95b144ae44", ip_address: "REDACTED", name: "TS-890", tcp_port: "60000", type: :tcp, user_is_admin: "false", user_name: "REDACTED", ...>, kns_user: %Open890.KNS.User{is_admin: "false", password: "REDACTED!", username: "REDACTED"}, radio_state: %Open890.RadioState{vd_meter: 0, active_mode: :usb, id_meter: 0, filter_state: %Open890.FilterState{hi_passband_id: 22, hi_shift: 2800, lo_passband_id: 3, lo_width: 200}, active_frequency: 14314030, ssb_filter_mode: :hi_lo_cut, band_scope_mode: :auto_scroll, ssb_data_filter_mode: :shift_width, fine: false, roofing_filter_data: %{a: 2700, b: 2700, c: 2700}, active_receiver: :b, squelch: 10, vfo_a_frequency: 3913000, band_scope_span: 50, audio_gain: 0, band_scope_avg: 1, mic_gain: 53, voip_available: true, alc_meter: 0, split_enabled: false, temp_meter: 0, cw_delay: 0, rf_att: 0, noise_blank_state: %Open890.NoiseBlankState{nb_1_enabled: false, nb_2_enabled: false}, projected_active_receiver_location: "", filter_high_freq: 14317530, cw_key_speed: 18, active_if_filter: :a, power_level: 50, inactive_frequency: 3913000, band_scope_fixed_span: nil, data_speed: 1, rit_xit_offset: 0, agc: :med, ref_level: 49, band_scope_edges: {14290000, 14340000}, notch_state: %Open890.NotchState{enabled: false, frequency: 72, width: :narrow}, nr: :off, apf_enabled: false, tx_state: :off, active_frequency_delta: -700, inactive_mode: :lsb, xit_enabled: false, swr_meter: 0, comp_meter: 0, s_meter: 11, vfo_memory_state: :vfo, ...}, socket: #Port<0.27>}
[info] Established TCP socket with radio on port 60000
[info] [UP] "##CN;"
[debug] Bandscope LV: RX connection_state: :up
[info] [UP] "##ID[REDACTED];"
[info] signed in, scheduling first ping
[info] [DN] "##TI1"
[debug] Dispatch: unknown message: "##TI1"
[info] Enabling audio scope via LAN
[info] [UP] "DD11;"
[info] Enabling LAN bandscope
[info] [UP] "DD01;"
[info] [UP] "AI2;"
[info] [UP] "FR;"
[info] [UP] "FR;"
[info] [UP] "FA;"
[info] [UP] "FB;"
[info] [UP] "BU0;"
[info] [UP] "BU1;"
[info] [UP] "SM;"
[info] [UP] "EX00611;"
[info] [UP] "EX00612;"
[info] [UP] "OM0;"
[info] [UP] "OM1;"
[info] [UP] "SH0;"
[info] [UP] "SL0;"
[info] [UP] "FS;"
[info] [UP] "FL0;"
[info] [UP] "FL10;"
[info] [UP] "FL11;"
[info] [UP] "FL12;"
[info] [UP] "BSO;"
[info] [UP] "BS3;"
[info] [UP] "BS4;"
[info] [UP] "BSM0;"
[info] [UP] "BSA;"
[info] [UP] "BS8;"
[info] [UP] "DS1;"
[info] [UP] "PA;"
[info] [UP] "RA;"
[info] [UP] "BSC;"
[info] [UP] "MV;"
[info] [UP] "RM11;"
[info] [UP] "RM21;"
[info] [UP] "DD0;"
[info] [UP] "AG;"
[info] [UP] "RG;"
[info] [UP] "PC;"
[info] [UP] "NT;"
[info] [UP] "NW;"
[info] [UP] "BP;"
[info] [UP] "XV;"
[info] [UP] "XO;"
[info] [UP] "AN;"
[info] [UP] "KS;"
[info] [UP] "SD;"
[info] [UP] "GC;"
[info] [UP] "MG;"
[info] [UP] "NR;"
[info] [UP] "BC;"
[info] [UP] "NB1;"
[info] [UP] "NB2;"
[info] [UP] "SQ;"
[info] [UP] "TB;"
[info] [UP] "AP0;"
[info] [UP] "##KN2;"
[info] [UP] "##VP;"
[info] [UP] "RT;"
[info] [UP] "XT;"
[info] [UP] "RF;"
[info] [DN] "SL031"
[warn] Unknown passband_id 31 for mode: unknown (filter_mode: unknown)
[info] [DN] "##KN21"
[info] [DN] "##VP0"
[info] [DN] "SL131"
[debug] Dispatch: unknown message: "SL131"
[info] [DN] "FR1"
[info] [DN] "FR1"
[info] [DN] "FA00003913000"
[info] [DN] "FB00014314030"
[info] [DN] "BU02"
[info] [DN] "BU12"
[info] [DN] "EX00611 001"
[info] [DN] "EX00612 001"
[info] [DN] "OM02"
[info] [DN] "OM11"
[info] [DN] "SH0029"
[info] [DN] "SL031"
[info] JOINED radio:audio_stream in 32µs

Tyrbiter commented 2 years ago

I don't have Cloudlog, which may or may not be relevant.

If you don't find the cause then I can repeat your test sequence if you like and see what happens.

I have noticed some glitchiness when selecting Radio from the connections page, it often seems to hang and then either retries or times out followed by the radio page opening as expected. Not sure if this could be related.

tonyc commented 2 years ago

I think the band scope edges are actually working fine, but I encountered this while testing it out. So the title of this ticket might actually change.

The crash isn't related to cloudlog in any way -- it seems like the code is trying to figure out which passband "ID" to use, and something is getting mucked up since it doesn't know the filter mode. Once the mode has changed in the menu, then it all recovers and is fine, so I wonder if the radio is sending the passband ID before the filter mode change.

Tyrbiter commented 2 years ago

OK, I saw the Cloudlog debug outputs, wondered if it might affect things.

I'm going to defer to your knowledge, I just don't have enough understanding of how the various parameters are sent across and interpreted. But please shout if extra testing is needed and I can rebuild and try things pretty rapidly.

tonyc commented 2 years ago

The cause of the problem is really annoying: the radio sends the filter info (hi/shift, low/width) BEFORE sending the message that the menu item changed, so open890 doesn't yet realize that menu 6-11 (6-12) changed. The code uses indexed lookup tables based on the command reference, so I'll need to attempt to detect this.

References #91

Tyrbiter commented 2 years ago

I suppose the only way to deal with this is to keep the state of things that can do this so that you compare the will-change-to values it sends to the was-set-to values you already have.

But then I'm no programmer and I don't know much about web-based event-driven programming.

tonyc commented 2 years ago

Encountered another one today while working on UI stuff. Mostly just leaving here for my own records:

[error] GenServer {:radio_connection_registry, {:tcp, "903e7dd4-38b7-4466-b48a-6b95b144ae44"}} terminating
** (ArithmeticError) bad argument in arithmetic expression
    :erlang.-(14101670, nil)
    (open890 0.1.0) lib/open890_web/radio_view_helpers.ex:155: Open890Web.RadioViewHelpers.offset_frequency_reverse/3
    (open890 0.1.0) lib/open890/radio_state.ex:661: Open890.RadioState.update_filter_lo_edge/1
    (open890 0.1.0) lib/open890/tcp_client.ex:307: Open890.TCPClient.handle_msg/2
    (elixir 1.12.3) lib/enum.ex:2385: Enum."-reduce/3-lists^foldl/2-0-"/3
    (open890 0.1.0) lib/open890/tcp_client.ex:76: Open890.TCPClient.handle_info/2
    (stdlib 3.14.2.2) gen_server.erl:689: :gen_server.try_dispatch/4
    (stdlib 3.14.2.2) gen_server.erl:765: :gen_server.handle_msg/6
    (stdlib 3.14.2.2) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
Last message: {:tcp, #Port<0.28>, "SL025;"}

Tyrbiter commented 2 years ago

I looked at the command reference, seems like they've made it easy to go beyond the effective filter cutoff frequency array bounds, which change with mode. It's not a clean interface.

tonyc commented 1 week ago

The problem here is that when the menu item changes (EX00611 001), the radio sends filter info down first, but not the reply that the menu item actually changed.

The solution may be to just "believe" that the menu item actually changed when sending the command, rather than when receiving the response from the radio.

Tyrbiter commented 1 week ago

Presumably it doesn't send the filter info unless the menu item has changed, so you can interpret the filter info as the confirmation of the change.

Only a problem if the same thing can happen in other situations, which I don't know.

tonyc commented 1 week ago

The problem is that you have to know what the menu setting is to properly interpret the "lo/width" and "hi/shift" messages.

So, here's what happens when sending the command to change the menu:

[up] change the menu item
[down] here's the low/width
[down] here's the high/shift
[down] ok, the menu item changed

What should happen:

[up] change the menu item
[down] ok, the menu item changed
[down] here's the low/width
[down] here's the high/shift

Anyway, I think I can get around it by just assuming the menu item changed when sending the command to change it, and then I'll know which filter mode the radio will be in, which then should cause the filter display to not crash :)

tonyc / open890

OTP crash while changing menu 6-11 or 6-12 #89