Not detecting lost connection in certain circumstances

[gbakeman]

It was discovered that under certain circumstances, WinNUT will not detect that a connection was dropped, the UPS Load and Remaining time fields will be reset, but the rest of the UI will appear as though it was still connected.

Reproduction

Due to the non-deterministic behavior of this bug, reproduction can be difficult. I've had a fair amount of success using a VirtualBox virtual machine, Windows 7 SP1 x64 guest, with two CPU cores and no execution cap. Chances of reproduction are higher when WinNUT's logging is turned off and no debugger is attached.

@yoyoma2's investigation

Posted:

I installed v2.3.9437 and put the username back in the "Login" text field. While running RaspiBackup (stops the NUT server and starts it hours later) WinNUT Client did not show any notifications and the icon in the taskbar did not change. I would expect a lost connection notification, a different icon until the a connected notification when the NUT server restarts. The old version did all that as long as the "Login" text field was empty.

Adds:

To get the bug I uncheck "Create Logfile" (Logging level stays at Debug), exit WinNUT client and reboot. The installer configured WinNUT client to run on startup only for my user. The stop/start of the server with the command above produces no notifications but hovering on the taskbar icon shows a strange -1%.

After that, opening the GUI shows the green UPS On Line but no dials refresh (we're not really connected). UPS Load is then always 0% even though the server is running again.

Last year I probably always had "Create Logfile" checked when I tested the debug build so the bug with having "Create Logfile" unchecked may have already been there.

Furthermore:

After it works with logging on, it will probably still work if logging is turned off. Sometimes after the bug I'll disconnect and reconnect manually from the connection menu so the dials can display properly again. After that the bug may or may not be reproducible. That's why I put reboot in the replication steps earlier because after rebooting with logging unchecked the bug always happens. Seems like an initialization thing.

Related

• Connected pop up not appearing after reconnecting in some situations #182
• Log files are always the same file size and length. #191
• Enhance Logging #93

[yoyoma2]

It's a timing thing. The tiny delay introduced by the logging after a socket error fixes the issue. After introducing a deliberate 1 msec delay I can no longer reproduce it with logging off.

diff --git a/WinNUT_V2/WinNUT-Client_Common/UPS_Device.vb b/WinNUT_V2/WinNUT-Client_Common/UPS_Device.vb
index 64dcf2e..4c7239a 100644
--- a/WinNUT_V2/WinNUT-Client_Common/UPS_Device.vb
+++ b/WinNUT_V2/WinNUT-Client_Common/UPS_Device.vb
@@ -483,6 +483,7 @@ Public Class UPS_Device
                         End If

                     Case Else
+                        Threading.Thread.Sleep(1) ' After a socket error, pause a little bit
                         LogFile.LogTracing("Error with " & varName & ", trying next", LogLvl.LOG_WARNING, Me)
                         ' Continue to next variable
                         Continue For

[gbakeman]

Good work on narrowing down the issue, it definitely seems like some kind of race condition. A change was recently added to the code that processes variables, so that multiple alternatives can be searched for in case an expected variable is not found (which is where this code is.) I'm still mystified how this is causing WinNUT to not notice the socket breaking when the NUT server goes down, and I have to wonder if there's a deeper problem here. If you don't mind, I'd like to investigate this a little further.

I made some progress over the weekend; I configured WinNUT as close as possible to the instance on my VM as on my dev machine, and yet they both behaved differently (VM WinNUT displays the issue you're seeing, yet my dev machine still does not), so next step in my mind is to attempt remote debugging with Visual Studio. Some technical issues with VirtualBox slowed me down and I haven't had a chance yet to connect the debugger, so work continues on that this week. Thanks again for your efforts and patience!

[yoyoma2]

Definitely worth taking the time to get a better understanding and the best possible fix.

• I'm seeing the issue on a bare metal install so no VM involved. The NUT server is on a raspberry pi on the same 1 Gb/s switch as the PC.
• My dev machine is 5 years old so probably slower than yours. Your VM is getting a subset of the resources so also slower than bare metal.
• With timing issues/race conditions the window of opportunity for problems often widens on slower or busy systems.
• Many UPS's use a serial to USB adapter so the communication channel is super slow relative the CPU.

The "AddHandler" type mechanisms are often implemented with threads. I've seen strange bugs disappear on massive real time systems by adding a call to sleep zero nanoseconds. The sleep calls on many OS's are an opportunity for the scheduler to give other threads a chance.

Why is the Select Case clause using an Else? Probably a dumb question but could this be narrowed down and throw an exception in a specific case? A deterministic fix would be better than hoping the scheduler is giving all threads enough time to make things work.

[gbakeman]

It sounds like you have quite a lot more knowledge than me on this! 😅 I recall spending some time previously understanding (or trying to) the different forms of async programming models in the .Net Framework, even implementing some form of Event Async Programming in the registry settings import system (which ended up being completely unnecessary for the workload, but it was good practice I hope.) Now that we're facing this bug, my assumptions and understanding is certainly challenged. WinNUT exclusively (AFAIK) uses WinForms and WinForm Timer objects which should be on the same UI thread, and taking a peek in the debugger shows only a single Main Thread. Perhaps then, the WinForms UI thread is doing some internal pseudo-threading to synchronize the main UI operation with any Timer objects I happen to have running - hence the race condition.

Since I last posted, I tried spending more time reproducing the issue. Going off of your hints, I reduced my VM to a single CPU core, limited its execution cap to ~20% and even ran a batch script with a simple loop to add some synthetic CPU load. While it appeared to significantly slow the machine down, it virtually guaranteed bug-free operation. I've now restored it to two CPU cores and 100% execution cap, and this has restored the reproduction chances to about ~75%, assuming logging is still off and I haven't connected the remote debugger. I want to add that I did manage to produce the bug with logging enabled (once), and only with informational logging so no advanced debug output:

11/12/2025 12:39:15 PM [2776, Nut_Socket]: Authenticated successfully.
11/12/2025 12:39:18 PM [2776, UPS_Device]: UPS statuses have CHANGED...
11/12/2025 12:39:18 PM [2776, UPS_Device]: Current statuses: OB,HB
11/12/2025 12:39:18 PM [2776, WinNUT]: dummy has switched to battery power.
11/12/2025 12:39:21 PM [2776, Logger]: Exception report complete.
11/12/2025 12:39:26 PM [2776, WinNUT]: Received FormClosing event. Reason: ApplicationExitCall
11/12/2025 12:39:26 PM [2776, Logger]: Exception report complete.
11/12/2025 12:39:26 PM [2776, WinNUT]: Disconnected from Nut Host

Right around that first Exception report complete line is when the bug displayed its self. Could just be a normal exception or something more serious. I also made the same observation you did, how the UPS Load goes to zero and the remaining time is lost, but everything else is frozen. When the machine was slowed down significantly, I could still see this gradual process of the UPS Load and Remaining time fields being reverted, and then everything else following in a normal reset operation. So there must be something relating to the code in WinNUT that resets the UI.

Why is the Select Case clause using an Else? Probably a dumb question but could this be narrowed down and throw an exception in a specific case? A deterministic fix would be better than hoping the scheduler is giving all threads enough time to make things work.

I admit that when the PR was made to modify this part of the code, I gave it a once-over, short test and a LGTM. I'll spend some more time understanding it with hopefully a fix to follow shortly.

[gbakeman]

Looking closer at the code now, and specifically the Select Case block, I recall wanting to handle a few cases of NUT protocol errors to record log messages on the problem. The DATASTALE error specifically required some special handling to re-attempt retrieval of the variable (something I did in #25). Although, I'm curious why execution would be reaching the Else case for you. Overall, I think I want to restructure this code a bit. My understanding is that it's expensive to create and throw exceptions in .NET and best practices dictate that you should avoid it when possible, especially considering that WinNUT doesn't remember invalid variables and keeps hammering the NUT server for them ad infinitum. I think I'd want to move this special case handling code up into the Else block before we throw any exceptions over NUT errors, and at least drop a log line when some exotic error is encountered. The generic Exception will be retained for other situations (such as broken sockets) so WinNUT can handle that higher-up. Of course, looking back over this reminds me how I still want to make greater structural changes in WinNUT to be a little more cleaner and maintainable... but that will have to wait. I haven't even gotten to the UI code yet to see why only the UPS Load and remaining time values are reset while everything else is frozen. Anyhow, in the meantime, let me have a few more days to chew on this and I should have (yet another) debug build for you to try out.

Thanks again for everything.

[yoyoma2]

My experience is mostly *nix. Your .NET knowledge is much greater and less dated.

I'm curious why execution would be reaching the Else case for you.

I'll try to investigate and report my findings. The more information, the better the understanding, the better the fix.

Thanks again for everything.

This bug is quite challenging and thus quite fun. I read your detailed progress report with great interest. Thanks for sharing.

[yoyoma2]

If I handle the NORESPONSE case separately the problem is also unreproducible with logging off. I just copied/tweaked the DATASTALE log message but since RawResponse is empty after a NORESPONSE it doesn't make sense to log it. Notice that the sleep call is now zero milliseconds and it still works. Not sure what mechanism kicks in during the Sleep(0) but it makes sense to do something after the NORESPONSE instead of going full steam ahead.

diff --git a/WinNUT_V2/WinNUT-Client_Common/UPS_Device.vb b/WinNUT_V2/WinNUT-Client_Common/UPS_Device.vb
index 64dcf2e..c4528a0 100644
--- a/WinNUT_V2/WinNUT-Client_Common/UPS_Device.vb
+++ b/WinNUT_V2/WinNUT-Client_Common/UPS_Device.vb
@@ -482,6 +482,11 @@ Public Class UPS_Device
                             End If
                         End If

+                    Case NUTResponse.NORESPONSE
+                        LogFile.LogTracing("NORESPONSE Error Result On Retrieving " & varName & " : " & ex
.LastTransaction.RawResponse, LogLvl.LOG_ERROR, Me)
+                        Threading.Thread.Sleep(0) ' After a NORESPONSE error, pause a little bit
+                        Continue For
+
                     Case Else
                         LogFile.LogTracing("Error with " & varName & ", trying next", LogLvl.LOG_WARNING, Me)
                         ' Continue to next variable

Just debugging/diagnostic code. You choose the best fix.