Winvnc 1.2.0.6/8 service problem after system restart

[Prisma]

Hi Rudi,

we use winvnc 1.2.0.6/8 now as a service with permanent reverse connection to the new repeater.
Some servers do not come back to the repeater after a system restart. Once logged in as user (console or rdp), the server appears on repeater.
Before and after logon both winvnc.exes (service and application part) do exist. This leads me to following assumption:
The application part could get a problem during the system startup and stops working.
The login process leads to have the service part to restart the application part (I remember you told me something like that ages before).
Therefore the server appears on the repeater now.

Configuring the service for delayed start helps in most cases.
Are there any dependencies the application part could have that are not resolved during startup, which leads him to stop working?

Any idea would be very appreciated.

[Rudi De Vos]

It seems only to happen with a reverse auto connect.

*if winvnc.exe is closed, service restart
*if network breaks, winvnc reconnect

The only difference between a normal and a invers service is that the network makes an outgoing connection on service start.
All desktops stuff is even not activated, on invers connection vnc just make a tcp connect and this is shown in the repeater.

Logon stop vnc in session a and start in sessionb, this is forced by service. winvnc is restarted.

Possible cause
Tcp isn't active or blocked during service start, possible starting the firewall after winvnc block something.
Try to make the vnc service depend on something like "windows update" i'm sure this one is stared as one of the last services.

[Prisma]

Still have problems. Latest possible start doesn't do the job.

On some machines login via RDP helps and winvnc appears again on repeater.
On some machines or sometimes we need to kill the second winvnc and let the service restart it. Then winvnc appears again on repeater.
These are all Servers runnig 24/7. The problem is related to system reboot and for this reason related with windows update. There is no other reason for the systems to reboot.
All Servers do not have a desktop firewall beside windows firewall. The servers are all behind SOHO NAT firewalls and repeater itself is also behind a SOHO NAT firewall with forwarded ports.
But the keepalives should prevent any kind of problems with hardware firewalls anyway.


It seems to be really repeatable. And easy to set up. Would be helpful if anyone other (you Rudi?) could try to reproduce it.
Or is there any debug logging I could activate to get closer to the problem? This was the easiest way.

[Prisma]

Hello Rudi,

we still have the problem above. Would you please provide us info how to activate/build debug logging or something similar.

Cheers

[Rudi De Vos]

There is one one server option

Logging
[v] log debug info to winvnc.log

[happy]

hi,

my fix for this problem is to schedule on all computers with uvnc and repeater a service restart using task scheduler.

I made bat files for:

- uvnx_service restart:

Code: Select all

net stop "uvnc_service"
net start "uvnc_service"

- repeater_service restart:

Code: Select all

net stop "repeater_service"
net start "repeater_service"

and I run them using task scheduler after system start or user login; first run with a 5-10 min delay and a repeating interval of 1-4h.

this way I am sure that if network connection is changed after start up - ( for example if it use VPN then connection to repeater is lost and never come back ) comp will still be found after service restart.

[Prisma]

Thanks for reply. I though about something similar. But to be honest, this can't be the solution for our problem. Possibly a temporary workaround.
So I tried to find the problem and activate debug logging as mentioned here:
http://forum.ultravnc.info/viewtopic.php?t=15475

with:

Code: Select all

[Admin]
DebugLevel=12
DebugMode=1

But nothing happens. I think I need a debug build. Is anybody able to help me out?

[Rudi De Vos]

DebugMode=2 <<<< save to file
path=C:\temp <<< path of winvnc.log
DebugLevel=10 << level of debug mode

Debugmode
const int VNCLog::ToDebug = 1; <<< send to Visual studio our windbg
const int VNCLog::ToFile = 2; << saved to file
const int VNCLog::ToConsole = 4; << show in a cmd window

WIth a service always use tofile.

[Prisma]

THX Rudi, works! A little bit to good. Because every 5 seconds following "error" appears:

Code: Select all

vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - Error: Usersize 0
vncproperties.cpp : ***** DBG - Force USER SYSTEM 2
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - Error: Usersize 0
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - Error: Usersize 0
vncmenu.cpp : ############### Usernames change: old="", new=""

This might be no error, but makes the logfile huge and it's hard to find the real error within a logfile of multiple MB where every 5 lines the keyword "Error" appears.
Before I choose a lower loglevel by try and error, what would be a good level to have a good chance to see the real error and not see the "spam" above. Or is this no "spam" and a real problem?

[Rudi De Vos]

The logging can become huge and some info isn't relevant.

This part of the logging show the 5 minute try to set the tray icon.
The function to ask the desktop user fail, this is an error, but normal when at that moment no user is logged on.
For me it's also an indication that the internal loop is correct running and that nobody is logged on.
The vnc logging need to becompared with the spots that generate the errors in the src to have a clue why something happen.

If i can repeat an issue, it's usual solved in 15 minutes, service stuff can be longer (hell to debug)
The biggest problem is to repeat it...
Problems that happen general are solved, but things that happen only in special cases can still exist.

Prisma, you are already using ultravnc for a long time and if you have multiple pc running it you must have
some idea how it can be repeated, what special things need to exist before it happen...

[Prisma]

For me it's also an indication that the internal loop is correct running and that nobody is logged on.

I copied the log snippet while being logged in via RDP. For the service which is capturing console only nobody is logged in. Your right. And I agree, at this time the internal loop seems to run. At this time the problem even doesn't exist. But:

Code: Select all

DisableTrayIcon=1

So, I would have expected that winvnc.exe does not try every 5 seconds (not minutes) to set something what is not needed to be set.

But anyway, that's not the main problem here. Yes, we use winvnc since ages. Therefore I try to do not bother you with newbie questions and I try to dig by myself as much as I can.
I also have an idea which happens before. A reboot. I'll get back to you when the problem of disappearing servers happens again. And I hope to be able to filter irrelevant errors out.

Cheers Greg.

[Prisma]

OK, got something. Today I came back in office and couldn't find a certain server at the repeater. I logged in with RDP and the server appears on repeater. I inspected the logfile and found the point where I logged in via RDP. From this point on I went backwards until I found an error. And voila, here is the latest error:

Code: Select all

Tue Nov 17 03:47:01 2015
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ########### Shell_TrayWnd found 1
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ############### Usernames change: old="foo", new="foo"
Tue Nov 17 03:47:06 2015
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ########### Shell_TrayWnd found 1
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ############### Usernames change: old="foo", new="foo"
Tue Nov 17 03:47:09 2015
vsocket.cpp : socket error 1: 10054
 --Eine vorhandene Verbindung wurde vom Remotehost geschlossen.
Tue Nov 17 03:47:11 2015
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ########### Shell_TrayWnd found 1
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ############### Usernames change: old="foo", new="foo"
Tue Nov 17 03:47:16 2015
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ########### Shell_TrayWnd found 1
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ############### Usernames change: old="foo", new="foo"
Tue Nov 17 03:47:19 2015
vncclient.cpp : PostAddNewClient I
vncservice.cpp : PostAddNewClient failed
vncserver.cpp : removing unauthorised client
vncserver.cpp : RemoveClient() done
vncclient.cpp : ~vncClient() executing...
vncclient.cpp : deleting socket
vsocket.cpp : closing socket
Tue Nov 17 03:47:21 2015
HideDesktop.cpp : Restorewallpaper 0
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : Add client reconnect from timer
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ########### Shell_TrayWnd found 1
vncserver.cpp : AutoConnectRetry(): started
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ############### Usernames change: old="foo", new="foo"
vncserver.cpp : Attempting AutoReconnect....
vsocket.cpp : VSocket() m_pDSMPlugin = NULL 
vncserver.cpp : AddClient() started
vncclient.cpp : vncClient() executing...
vncclient.cpp : TEST 4
vncserver.cpp : AddClient() done
vncclient.cpp : client connected : 8x.21x.11x.21x (1)
vncclient.cpp : DSMPlugin Pointer to socket OK
Tue Nov 17 03:47:26 2015
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ########### Shell_TrayWnd found 1
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ############### Usernames change: old="foo", new="foo"
Tue Nov 17 03:47:31 2015
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ########### Shell_TrayWnd found 1
vncservice.cpp : @@@@@@@@@@@@@ GetCurrentUser - UserNAme found: foo 
 --Überlappender E/A-Vorgang wird verarbeitet.
vncmenu.cpp : ############### Usernames change: old="foo", new="foo"

Seems to be the ISPs internet hangup on servers side. In Germany some ISPs drop the line frequently. The repeater has no hangup until now, other ISP. What I don't understand is the server seems to reconnect (AddClient done). But I bet, from this time on the server isn't visible on the repeater.

I furthermore inspected the log and found an earlier socket error:

Code: Select all

Mon Nov 16 14:01:47 2015
vsocket.cpp : socket error 1: 10054
 --Eine vorhandene Verbindung wurde vom Remotehost geschlossen.
vncclient.cpp : PostAddNewClient I
vncservice.cpp : PostAddNewClient failed
vncserver.cpp : removing unauthorised client
vncserver.cpp : RemoveClient() done
vncclient.cpp : ~vncClient() executing...
vncclient.cpp : deleting socket
vsocket.cpp : closing socket

The only differences I'm able to see is that at this time the socket error was immediately detected, and after this hangup there was no problem. Only after the hangup I reported above.

Any Idea? How to get closer to that problem?

[Rudi De Vos]

Does the server ip stay the same, i mean the external ip ( internet or nat router ip).
Server with id 1234 and ip 123.123.123.13 announche himself to the repeater
server with id 1234 and ip 123.123.123.14 announche himself to the repeater

WIth a isp reset, i guess both repeater/server link stay on, but some inter connection is broken.

[Prisma]

In Germany normally you get a new external ip on a ISP reset.
What do you mean with some inter connection is broken? Do you think you're able to fix this?

[Rudi De Vos]

Don't know yet, i first need to be able to repeat it.
Perhaps setting a static ip address and then do a manual change...

[Prisma]

yes, it's a good idea for testing. But if you change a NICs static ip manually, the OS knows that something changed. If the router got a new external IP, the OS doesn't recognize this.

I think you should be able to reproduce it if you take a router and put it between your development computer an your local Network with repeater.
If you configure the router as DHCP client and you configure changing reservations for the routers MAC on your DHCP server, it's the same situation like with german ISPs.
But it should have the same effect and would be much easier to configure the routers WAN address static without DHCP but change the IP manually.

[Rudi De Vos]

Test
PC<-> (hub)<->(nat router)<->internet<->(repeater)
reset nat router

PC sees the socket going down, socket rcv error and restart
Reconnect to repeater until the net is back online and connect OK

Repeater still show
OLD IP 123.123.123.123 with id 123456
server add
NEW IP 123.123.123.222 with id 123456
Then repeater remove old but new is not added
Server is still online, so socket isn't broken by repeater

Looks like a repeater isuue, possible some protection against ID stealing we added.
We have -> 2 different (ip1!=ip2) server try to use the same ID

[Prisma]

I'm very relieved you found the reason. Thank you.

The least invasive change to the repeater was a configuration setting to disable this protection. This was a risk we could live with. (Customers with dual/tripel/multi wan routers use to have also changing ip addresses)

What about this idea:
* let the server with new IP connect and keep it on hold (I think this is what happens at the moment)
* wait until loss of connection of ID with old IP is detected and ID is removed
* then accept the changed IP an expose the ID again to the viewer

I think this is acceptable in terms of the safety aspect. For customers with multi wan routers this would be also ok.

[Rudi De Vos]

This seems to work
When the same ID is used by another ip, i just replace the old ID by 999999999.

Then everything stay the same as before, threads keep running and the 9999 should be auto cleaned after
a while by the current cleanup functions. Repeater is stable and i don't want to change a lot.

test download
http://www.uvnc.eu/download/repeater/repeater2015.zip

--------------------------------------------------------------------------------------------
I have 2 servers with same ID, 127 kick 192 and invers,
Natural, when the ip change happen on the same server, you don't compete for a slot.

Slot Time ID nummer Connection from comment
0 2015/11/21 15:19:50 999999999 192.168.1.6
1 2015/11/21 15:20:10 999999999 127.0.0.1
2 2015/11/21 15:20:29 12345678 192.168.1.6

Waiting servers:

Slot Time ID nummer Connection from comment
0 2015/11/21 15:29:44 999999999 192.168.1.6
1 2015/11/21 15:29:46 12345678 127.0.0.1

[Prisma]

THX a lot, Rudi. 2015 Version is running now in productive environment.
Longterm tests will show whether this was the only reason for the noticed behaviour. I'll keep you informed.

Cheers Greg

[Prisma]

Sorry, but after changing repeater2014 to repeater2015 something is unstable.
Every X minutes all servers disappear from repeater. Probably every 15 minutes or more often. I'm not able to observe repeater's webgui all the time.
After a view minutes all servers are back.

[Prisma]

No, it's more often. Have to switch back to repeater2014.

FYI: Our repeater service is restarted automatically after a crash. But no crash is reported within eventviewer. Possible repeater.exe terminates unrecognised? Or it's just another bug, which simply makes all servers disappear... However...

[Rudi De Vos]

SO it looks like the src i used isn't the correct one, just changing the ID can't have this effect.

[Rudi De Vos]

re uploaded
http://www.uvnc.eu/download/repeater/repeater2015.zip

code was 12/2014 correct
cleanup function was set to 1 sec for fast tesing, fixed.

All added to svn, to compare change and avoid version mismatch

[Prisma]

New version running. Looks good. All servers still on repeater. We observe this a few days, but seems solved.