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

WinNUT endless reconnect cycle with NUT server from OPNsense | INVALIDARGUMENT | FormatException #128

Closed
3 tasks done
codiflow opened this issue Jan 25, 2024 · 3 comments
Closed
3 tasks done

WinNUT endless reconnect cycle with NUT server from OPNsense | INVALIDARGUMENT | FormatException #128

codiflow opened this issue Jan 25, 2024 · 3 comments
Assignees
@gbakeman
Labels
bug Something isn't working duplicate This issue or pull request already exists

Comments

@codiflow
Copy link

codiflow commented Jan 25, 2024 •
edited
Loading

  • Completed below form
  • Attached debug log file
  • Copy output in File -> UPS Variable

WinNUT Version: 2.2.8719.24624
Windows OS Version: Windows Server 2016 1607 (Build 14393.6529)

Describe the bug
WinNUT permanently disconnects from NUT running on OPNsense.
WinNUT is not reconnecting to the NUT service anymore which has worked just fine a few months ago (I did not track this down immediately as it worked again sometimes). It tries to connect and after the "poll intervall" period it tries to reconnect – see the logs. As this has worked before the only things that changed were the update to the most recent WinNUT version and indeed OPNsense updates.

The setup is as follows:
The UPS is connected via USB to the OPNsense firewall. The APCUPSd is the main UPS server on this firewall also providing a netserver instance. The NUT server on OPNsense internally connects to the APCUPSd netserver daemon and provides a NUT server for other devices. This way we can use NUT and APCUPSd in parallel in our network.

Unfortunately I don't have any logs on OPNsense side which could provide additional hints.

There's also a Synology NAS which is connected to the same NUT server and it just works fine – no issues.

Expected behavior
Connection should be established and remain stable.

Additional context
Debug log from WinNUT:

WinNUT Client - 2.2
Verbindung zu 192.168.0.1:3493 verloren
25.01.2024 13:15:29 [2752, WinNUT]: Battery Status => Unknown
25.01.2024 13:15:29 [2752, WinNUT]: Update Icon
25.01.2024 13:15:29 [2752, UPS_Device]: Reconnection Process Started
25.01.2024 13:15:34 [2752, WinNUT]: NotifyIcon Text => 
WinNUT Client - 2.2
Wiederverbindung läuft
Versuch 1 von 30
25.01.2024 13:15:34 [2752, WinNUT]: Update Icon
25.01.2024 13:15:34 [2752, UPS_Device]: Try Reconnect 1 / 30
25.01.2024 13:15:34 [2752, String]: New Log to CB_Current Log : Versuche Wiederverbindung 1 / 30
25.01.2024 13:15:34 [2752, UPS_Device]: Beginning connection: admin@192.168.0.1:3493, Name: ups [AutoReconnect]
25.01.2024 13:15:34 [2752, Nut_Socket]: Attempting TCP socket connection to 192.168.0.1:3493...
25.01.2024 13:15:34 [2752, Nut_Socket]: Connection established and streams ready for 192.168.0.1:3493
25.01.2024 13:15:34 [2752, Nut_Socket]: Attempting authentication...
25.01.2024 13:15:34 [2752, Nut_Socket]: Error while attempting to log in: INVALIDARGUMENT (ERR INVALID-ARGUMENT)
Query: LOGIN
25.01.2024 13:15:34 [2752, Nut_Socket]: NUT server reports VER: 2.8.1 NETVER: 
25.01.2024 13:15:34 [2752, UPS_Device]: ups.realpower is not supported by server.
25.01.2024 13:15:34 [2752, UPS_Device]: Unhandled error while getting ups.realpower
25.01.2024 13:15:34 [2752, UPS_Device]: Using NominalPowerCalc method to calculate power usage.
25.01.2024 13:15:34 [2752, UPS_Device]: battery.capacity is not supported by server.
25.01.2024 13:15:34 [2752, UPS_Device]: Apply Fallback Value when retrieving battery.capacity
25.01.2024 13:15:34 [2752, UPS_Device]: output.frequency.nominal is not supported by server.
25.01.2024 13:15:34 [2752, UPS_Device]: Apply Fallback Value when retrieving output.frequency.nominal
25.01.2024 13:15:34 [2752, WinNUT]: ups has indicated it's ready to start sending data.
25.01.2024 13:15:34 [2752, WinNUT]: Update Icon
25.01.2024 13:15:34 [2752, WinNUT]: NotifyIcon Text => 
WinNUT Client - 2.2
Verbunden
25.01.2024 13:15:34 [2752, WinNUT]: Connection to Nut Host Established
25.01.2024 13:15:34 [2752, String]: New Log to CB_Current Log : Verbindung zum Nut Host 192.168.0.1:3493 hergestellt
25.01.2024 13:15:34 [2752, UPS_Device]: Nut Host Reconnected
25.01.2024 13:15:34 [2752, WinNUT]: ups has indicated it's ready to start sending data.
25.01.2024 13:15:34 [2752, WinNUT]: Update Icon
25.01.2024 13:15:34 [2752, WinNUT]: NotifyIcon Text => 
WinNUT Client - 2.2
Verbunden
25.01.2024 13:15:34 [2752, WinNUT]: Connection to Nut Host Established
25.01.2024 13:15:34 [2752, String]: New Log to CB_Current Log : Verbindung zum Nut Host 192.168.0.1:3493 hergestellt
25.01.2024 13:15:39 [2752, UPS_Device]: Enter Retrieve_UPS_Datas
25.01.2024 13:15:39 [2752, UPS_Device]: output.frequency is not supported by server.
25.01.2024 13:15:39 [2752, UPS_Device]: Apply Fallback Value when retrieving output.frequency
25.01.2024 13:15:39 [2752, UPS_Device]: input.frequency is not supported by server.
25.01.2024 13:15:39 [2752, UPS_Device]: Apply Fallback Value when retrieving input.frequency
25.01.2024 13:15:39 [2752, UPS_Device]: output.voltage is not supported by server.
25.01.2024 13:15:39 [2752, UPS_Device]: Apply Fallback Value when retrieving output.voltage
25.01.2024 13:15:39 [2752, UPS_Device]: Something went wrong in Retrieve_UPS_Datas: System.FormatException: Die Eingabezeichenfolge hat das falsche Format.
   bei System.Number.StringToNumber(String str, NumberStyles options, NumberBuffer& number, NumberFormatInfo info, Boolean parseDecimal)
   bei System.Number.ParseInt32(String s, NumberStyles style, NumberFormatInfo info)
   bei WinNUT_Client_Common.UPS_Device.GetPowerUsage()
   bei WinNUT_Client_Common.UPS_Device.Retrieve_UPS_Datas()
25.01.2024 13:15:39 [2752, UPS_Device]: Processing request to disconnect...
25.01.2024 13:15:39 [2752, WinNUT]: Update all informations displayed to empty values
25.01.2024 13:15:39 [2752, WinNUT]: Update Icon
25.01.2024 13:15:39 [2752, WinNUT]: Status Icon Changed
25.01.2024 13:15:39 [2752, WinNUT]: New Icon Value For Systray : 1216
25.01.2024 13:15:39 [2752, WinNUT]: New Icon Value For Gui : 1216
25.01.2024 13:15:39 [2752, WinNUT]: NotifyIcon Text => 
WinNUT Client - 2.2
Nicht verbunden
25.01.2024 13:15:39 [2752, WinNUT]: Battery Status => Unknown
25.01.2024 13:15:39 [2752, WinNUT]: Disconnected from Nut Host
25.01.2024 13:15:39 [2752, String]: New Log to CB_Current Log : Verbindung zum NUT-Host verloren
25.01.2024 13:15:39 [2752, UPS_Device]: Socket has reported a Broken event.
25.01.2024 13:15:39 [2752, WinNUT]: Notify user of lost connection
25.01.2024 13:15:39 [2752, String]: New Log to CB_Current Log : Verbindung zu 192.168.0.1:3493 verloren
25.01.2024 13:15:39 [2752, WinNUT]: Update all informations displayed to empty values
25.01.2024 13:15:39 [2752, WinNUT]: Status Icon Changed
25.01.2024 13:15:39 [2752, WinNUT]: New Icon Value For Systray : 1344
25.01.2024 13:15:39 [2752, WinNUT]: New Icon Value For Gui : 1344
25.01.2024 13:15:39 [2752, WinNUT]: NotifyIcon Text => 
WinNUT Client - 2.2
Verbindung zu 192.168.0.1:3493 verloren
25.01.2024 13:15:39 [2752, WinNUT]: Battery Status => Unknown
25.01.2024 13:15:39 [2752, WinNUT]: Update Icon
25.01.2024 13:15:39 [2752, UPS_Device]: Reconnection Process Started

UPS variables:

ups (APC/Back-UPS RS 900G/879.L4 .I USB FW:L4)
battery.charge (Battery charge (percent of full)) : 100.0
battery.charge.low (Remaining battery level when UPS switches to LB (percent)) : 25
battery.date (Battery change date) : 2022-01-29
battery.runtime (Battery runtime (seconds)) : 3048.0
battery.runtime.low (Remaining battery runtime when UPS switches to LB (seconds)) : 300
battery.voltage (Battery voltage (V)) : 27.1
battery.voltage.nominal (Nominal battery voltage (V)) : 24.0
device.mfr (Description unavailable) : APC
device.model (Description unavailable) : Back-UPS RS 900G
device.serial (Description unavailable) : <REDACTED>
device.type (Description unavailable) : ups
driver.debug (Current debug verbosity level of the driver program) : 0
driver.flag.allow_killpower (Safety flip-switch to allow the driver daemon to send UPS shutdown command (accessible via driver.killpower)) : 0
driver.name (Driver name) : apcupsd-ups
driver.parameter.pollinterval (Description unavailable) : 10
driver.parameter.port (Description unavailable) : 192.168.0.1:3551
driver.parameter.synchronous (Description unavailable) : auto
driver.state (Description unavailable) : quiet
driver.version (Driver version - NUT release) : 2.8.1
driver.version.internal (Internal driver version) : 0.71
input.sensitivity (Input power sensitivity) : M
input.transfer.high (High voltage transfer point (V)) : 294.0
input.transfer.low (Low voltage transfer point (V)) : 176.0
input.transfer.reason (Reason for last transfer to battery) : No transfers since turnon
input.voltage (Input voltage (V)) : 230.0
input.voltage.nominal (Nominal input voltage (V)) : 230
ups.date (Internal UPS clock date) : 2024-01-25
ups.firmware (UPS firmware) : 879.L4 .I USB FW:L4
ups.id (UPS system identifier) : Back-UPS RS 900G
ups.load (Load on UPS (percent of full)) : 21.0
ups.mfr (UPS manufacturer) : APC
ups.model (UPS model) : Back-UPS RS 900G
ups.realpower.nominal (UPS real power rating (W)) : 540.0
ups.serial (UPS serial number) : <REDACTED>
ups.status (UPS status) : OL
ups.test.result (Results of last self test) : NO
ups.time (Internal UPS clock time) : 13:17:23

While I wanted to copy the UPS variables also this error appeared – maybe this has to do with WinNUT not having been connected to the UPS at this very moment?

System.Runtime.InteropServices.ExternalException (0x800401D0): Der angeforderte Clipboard-Vorgang war nicht erfolgreich.
   bei System.Windows.Forms.Clipboard.ThrowIfFailed(Int32 hr)
   bei System.Windows.Forms.Clipboard.SetDataObject(Object data, Boolean copy, Int32 retryTimes, Int32 retryDelay)
   bei System.Windows.Forms.Clipboard.SetText(String text, TextDataFormat format)
   bei System.Windows.Forms.Clipboard.SetText(String text)
   bei WinNUT_Client.List_Var_Gui.Btn_Clip_Click(Object sender, EventArgs e)
   bei System.Windows.Forms.Control.OnClick(EventArgs e)
   bei System.Windows.Forms.Button.OnClick(EventArgs e)
   bei System.Windows.Forms.Button.OnMouseUp(MouseEventArgs mevent)
   bei System.Windows.Forms.Control.WmMouseUp(Message& m, MouseButtons button, Int32 clicks)
   bei System.Windows.Forms.Control.WndProc(Message& m)
   bei System.Windows.Forms.ButtonBase.WndProc(Message& m)
   bei System.Windows.Forms.Button.WndProc(Message& m)
   bei System.Windows.Forms.Control.ControlNativeWindow.OnMessage(Message& m)
   bei System.Windows.Forms.Control.ControlNativeWindow.WndProc(Message& m)
   bei System.Windows.Forms.NativeWindow.Callback(IntPtr hWnd, Int32 msg, IntPtr wparam, IntPtr lparam)
@codiflow codiflow added the bug Something isn't working label Jan 25, 2024
@codiflow codiflow changed the title WinNUT always reconnects after startup with NUT server from OPNsense | INVALIDARGUMENT | FormatException WinNUT endless reconnect cycle with NUT server from OPNsense | INVALIDARGUMENT | FormatException Jan 25, 2024
@gbakeman
Copy link
Contributor

gbakeman commented Jan 31, 2024 •
edited
Loading

Sorry I missed your issue report - for some reason I did not see an email about it.

This issue was addressed in Pre-Release v2.3.8754 (duplicate #123 ). Please update to that and let us know how it goes.

@gbakeman gbakeman added duplicate This issue or pull request already exists question Further information is requested labels Jan 31, 2024
@gbakeman
Copy link
Contributor

gbakeman commented Feb 8, 2024

Closing as duplicate

@gbakeman gbakeman closed this as not planned Won't fix, can't repro, duplicate, stale Feb 8, 2024
@gbakeman gbakeman removed the question Further information is requested label Feb 8, 2024
@codiflow
Copy link
Author

codiflow commented Feb 9, 2024

Sorry for my late response, Pre-Release v2.3.8754 fixed the issue.

Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@gbakeman gbakeman

Labels
bug Something isn't working duplicate This issue or pull request already exists
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@gbakeman @codiflow