To see this working, head to your live site.

VarAC Cluster Breaks - from Last Heard Peaking Multiband? SQLite Conflict! (V11.2.0)

in Bug reports

Bug:

VarAC Cluster breaks after receiving <LHR> (Last Heard Peaking request) with multiband peeking ON.

Note: I did NOT test LHR with multiband peeking off, and it may also be broken.

Scope:

Spotted in VarAC V11.2.0

Symptoms:

EMAIL GATE turns orange (it is supposed to remain blue) in the non-sender nodes.
Datastream messages window - discontinuity, some messages disappear or are not displayed after <LHR>.
A Vmail was LOST - after being received and confirmed with <SMR>, and parked! The Vmail disappeared from parked vmails and was lost.
The VarAC Cluster does NOT recover until closing ALL instances of VarAC and restarting them!

Analysis:

The log indicates SQLite database errors:

02/06/2025 22:12:04 - LHR tag identified (Last Heard Request)
02/06/2025 22:12:04 - Error: processing Request last heard callsign peeking request
02/06/2025 22:12:04 - Value was either too large or too small for an Int32.
at System.Convert.ToInt32(Int64 value)
at System.Int64.System.IConvertible.ToInt32(IFormatProvider provider)
at System.Convert.ToInt32(Object value)
at VarAC.VarAC.<connect_varahf_modem>b__126_2()
02/06/2025 22:12:11 - Error: updating instance keepalive in SQLite:database is locked
database is locked
at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
at System.Data.SQLite.SQLiteDataReader.NextResult()
at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()
at VarAC.VarAC.update_instance_keepalive(Int32 instance_id)
02/06/2025 22:12:11 - Error: updating instance keepalive in SQLite:database is locked
database is locked
at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
at System.Data.SQLite.SQLiteDataReader.NextResult()
at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()
at VarAC.VarAC.update_instance_keepalive(Int32 instance_id)
02/06/2025 22:12:15 - Error: Writing to SQLite datastream table :database is locked
database is locked
at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
at System.Data.SQLite.SQLiteDataReader.NextResult()
at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()
at VarAC.VarAC.write_datastream_log_to_db(String qso_guid, Int32 datastream_entry_type_id, String callsign, String entry, DateTime creation_time, Int32 chat_id, Int32 reply_on_chat_id, String file_path)
02/06/2025 22:12:27 - Error: Writing to cqframe table:database is locked
database is locked
at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
at System.Data.SQLite.SQLiteDataReader.NextResult()
at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()
at VarAC.VarAC.write_last_heard_to_db(DateTime cqframe_time, Int32 cqframe_type_id, Int64 frequency, String bandwidth, String from_callsign, Int32 snr, String slot, String data, String locator, Boolean is_emcomm, Boolean is_email_gateway)
02/06/2025 22:12:28 - PSKReporter: Logged successfully (4Z1AC)
02/06/2025 22:12:28 - PSKReporter: Sending accumulated records
02/06/2025 22:12:28 - Error: Writing to SQLite qso_snr_report table :database is locked
database is locked
at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
at System.Data.SQLite.SQLiteDataReader.NextResult()
at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()
at VarAC.VarAC.write_snr_to_db(String qso_guid, Int32 snr_direction, Int32 snr, DateTime creation_time)
02/06/2025 22:12:29 - Error: Writing to SQLite datastream table :database is locked
database is locked
at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
at System.Data.SQLite.SQLiteDataReader.NextResult()
at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()
at VarAC.VarAC.write_datastream_log_to_db(String qso_guid, Int32 datastream_entry_type_id, String callsign, String entry, DateTime creation_time, Int32 chat_id, Int32 reply_on_chat_id, String file_path)
02/06/2025 22:12:32 - Disable PTT status set to false
02/06/2025 22:12:32 - Setting disable ptt status to false
02/06/2025 22:13:00 - Closing Rig comport
02/06/2025 22:13:00 - Closing GPS comport
02/06/2025 22:13:00 - Closing Rig TCP port
02/06/2025 22:13:22 - Debug mode disabled
02/06/2025 22:13:22 - Instance number: 20
02/06/2025 22:13:23 - Error: updating instance email gateway status in SQLite:database is locked
database is locked
at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)
at System.Data.SQLite.SQLiteDataReader.NextResult()
at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)
at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)
at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()
at VarAC.VarAC.update_instance_email_gateway_status(Int32 instance_id, Boolean email_gateway_active, Boolean email_gateway_sender_node)
02/06/2025 22:13:23 - Setting unattended links ON (load) ...

Recommendation:

Fix the bugs indicated in the VarAC log, and fully test that Last Heard Peeking works in all cases.
Add additional sanity checks and error handling. I suggest: A. Display errors in the GUI and offer to send feedback/bug report to the developers. B. Then recover the cluster and all instances and the SQLite database to a sane and safe state, or instruct the end user how to do this.

Screen Capture of the Bug, Showing the Broken VarAC Cluster:

6 comments

6 Comments

irad d

Jun 03

ok - the processing of a QO-100 frequency error seems to start the whole sequence as the code only handled INT32 while 10GHZ is int64 (long)

Value was either too large or too small for an Int32.

I applied a fix on my end - but just to see if it can be reproduced to be sure - can you try and simulate an LHR without QO data and with (I know its kinda hard to simulate but maybe you can)

Irad

Meir 4Z5PE | QO100<->HF VarAC Cluster

Jun 10

Replying to

Hi Irad,

It's apparently still broken in V.11.4.0 - at least for my database with the parked email from QO-100!

10/06/2025 19:43:39 - Advanced Mode enabled

10/06/2025 19:43:39 - Opening DB connection

10/06/2025 19:43:39 - Current VarAC DB version: 27

10/06/2025 19:43:39 - Applications launcher disabled

10/06/2025 19:43:44 - Connecting VARA Main Modem Command interface...

10/06/2025 19:43:44 - Connecting VARA Main Modem data stream...

10/06/2025 19:43:44 - Connecting VARA Main Modem KISS Command interface...

10/06/2025 19:43:44 - Connected to VARA modem

10/06/2025 19:43:44 - Setting Bandwith to 500Hz

10/06/2025 19:43:48 - VarAC base directory: C:\Program Files\VarAC\

10/06/2025 19:43:48 - VARA version: VARA HF v4.8.9

10/06/2025 19:43:48 - Checking for VarAC update.

10/06/2025 19:44:33 - Email Gateway activated (Manually)

10/06/2025 19:44:34 - Error in mailbox_send_outbox_thread

10/06/2025 19:44:34 - Value was either too large or too small for an Int32.

at System.Convert.ToInt32(Int64 value)

at System.Int64.System.IConvertible.ToInt32(IFormatProvider provider)

at System.Convert.ToInt32(Object value)

at VarAC.VarAC.<connect_varahf_modem>b__126_7()

10/06/2025 19:44:35 - Error in mailbox_send_outbox_thread

10/06/2025 19:44:35 - Value was either too large or too small for an Int32.

at System.Convert.ToInt32(Int64 value)

at System.Int64.System.IConvertible.ToInt32(IFormatProvider provider)

at System.Convert.ToInt32(Object value)

at VarAC.VarAC.<connect_varahf_modem>b__126_7()

10/06/2025 19:44:36 - Error in mailbox_send_outbox_thread

10/06/2025 19:44:36 - Value was either too large or too small for an Int32.

at System.Convert.ToInt32(Int64 value)

at System.Int64.System.IConvertible.ToInt32(IFormatProvider provider)

at System.Convert.ToInt32(Object value)

at VarAC.VarAC.<connect_varahf_modem>b__126_7()

10/06/2025 19:44:37 - Error in mailbox_send_outbox_thread

10/06/2025 19:44:37 - Value was either too large or too small for an Int32.

at System.Convert.ToInt32(Int64 value)

at System.Int64.System.IConvertible.ToInt32(IFormatProvider provider)

at System.Convert.ToInt32(Object value)

at VarAC.VarAC.<connect_varahf_modem>b__126_7()

10/06/2025 19:44:38 - Error in mailbox_send_outbox_thread

10/06/2025 19:44:38 - Value was either too large or too small for an Int32.

at System.Convert.ToInt32(Int64 value)

at System.Int64.System.IConvertible.ToInt32(IFormatProvider provider)

at System.Convert.ToInt32(Object value)

at VarAC.VarAC.<connect_varahf_modem>b__126_7()

10/06/2025 19:44:39 - Error in mailbox_send_outbox_thread

10/06/2025 19:44:39 - Value was either too large or too small for an Int32.

at System.Convert.ToInt32(Int64 value)

at System.Int64.System.IConvertible.ToInt32(IFormatProvider provider)

at System.Convert.ToInt32(Object value)

at VarAC.VarAC.<connect_varahf_modem>b__126_7()

10/06/2025 19:44:41 - Error in mailbox_send_outbox_thread

10/06/2025 19:44:41 - Value was either too large or too small for an Int32.

at System.Convert.ToInt32(Int64 value)

at System.Int64.System.IConvertible.ToInt32(IFormatProvider provider)

at System.Convert.ToInt32(Object value)

at VarAC.VarAC.<connect_varahf_modem>b__126_7()

10/06/2025 19:45:07 - Email Gateway disabled (Manually)

10/06/2025 19:45:30 - KISS BEACON received from OH6CRU

10/06/2025 19:45:30 - PSKReporter: Logged successfully (OH6CRU)

10/06/2025 19:45:30 - PSKReporter: Sending accumulated records

10/06/2025 19:45:30 - Logging Contact to DB: OH6CRU

Edited

Meir 4Z5PE | QO100<->HF VarAC Cluster

Replying to

Hi Irad

Still seeing this error in V11.4.1!
The node is QO-100, freq=10.489.595.000.

Please see my comments, in bold, below.

04/07/2025 10:07:25 - Debug mode disabled

04/07/2025 10:07:25 - Instance number: 24

04/07/2025 10:07:25 - Setting away status to true (load)

04/07/2025 10:07:25 - Setting unattended links ON (load)

04/07/2025 10:07:25 - Resetting to Slot 0

04/07/2025 10:07:25 - Opening COM port

04/07/2025 10:07:59 - Connecting OH3DP

04/07/2025 10:08:18 - Disconnected from OH3DP

04/07/2025 10:10:03 - Away status set to false

04/07/2025 10:10:06 - Away status set to false

04/07/2025 10:10:11 - Away status set to false

04/07/2025 10:10:44 - Error: unable to load QSO data: Value was either too large or too small for an Int32.

at System.Convert.ToInt32(Int64 value)

at System.Int64.System.IConvertible.ToInt32(IFormatProvider provider)

at System.Convert.ToInt32(Object value)

at VarAC.VarAC.get_qso_details(String guid)

at VarAC.Form15.dg_ch_adif_history_SelectionChanged(Object sender, EventArgs e)

04/07/2025 10:10:44 - Error: unable to load QSO data: Value was either too large or too small for an Int32.

at System.Convert.ToInt32(Int64 value)

at System.Int64.System.IConvertible.ToInt32(IFormatProvider provider)

at System.Convert.ToInt32(Object value)

at VarAC.VarAC.get_qso_details(String guid)

at VarAC.Form15.dg_ch_adif_history_SelectionChanged(Object sender, EventArgs e)

04/07/2025 10:10:51 - Error: updating instance keepalive in SQLite:database is locked

database is locked

at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)

at System.Data.SQLite.SQLiteDataReader.NextResult()

at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)

at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)

at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)

at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()

at VarAC.VarAC.update_instance_keepalive(Int32 instance_id)

04/07/2025 10:10:51 - Error: updating instance keepalive in SQLite:database is locked

database is locked

at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)

at System.Data.SQLite.SQLiteDataReader.NextResult()

at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)

at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)

at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)

at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()

at VarAC.VarAC.update_instance_keepalive(Int32 instance_id)

04/07/2025 10:10:52 - Error: unable to update instance busy status in SQLite:database is locked

database is locked

at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)

at System.Data.SQLite.SQLiteDataReader.NextResult()

at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)

at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)

at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)

at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()

at VarAC.VarAC.update_instance_busy_state(Int32 instance_id, Boolean is_busy)

04/07/2025 10:10:52 - Error: unable to update instance busy status in SQLite:database is locked

database is locked

at System.Data.SQLite.SQLite3.Step(SQLiteStatement stmt)

at System.Data.SQLite.SQLiteDataReader.NextResult()

at System.Data.SQLite.SQLiteDataReader..ctor(SQLiteCommand cmd, CommandBehavior behave)

at System.Data.SQLite.SQLiteCommand.ExecuteReader(CommandBehavior behavior)

at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery(CommandBehavior behavior)

at System.Data.SQLite.SQLiteCommand.ExecuteNonQuery()

at VarAC.VarAC.update_instance_busy_state(Int32 instance_id, Boolean is_busy)

[The EMAIL GATE indicator turned ORANGE: No active sender node in the cluster!]

[Here I tried to add the Grid and Log the QSO manually, clicked the LOG button - and it FAILED!]

04/07/2025 10:12:08 - Unable to log QSO with OH3DP ,missing information

04/07/2025 10:12:08 - Logging QSO to DB: OH3DP

Edited

irad d

Replying to

Fixed that also in the callsign history form.

Will be out in V12.2 but I can send you a version to test if you want. Send me an email to iradirad@gmail.com