FOG Communication ERROR after power on (not after FOGservice restart)
-
Hi Guys
I’m running FOGTrunk 5566 with FOG client 0.9.7 on Windows 8.1 clients.
When I power on a Windows 8.1 client, the first time the FOG client service connects, it sometimes gives communication ERROR: Could not contact FOG server. After 60 seconds, the clients connects again to the FOG server, this time succesfully.
The big problem now is: the Authentication module only communicates with the FOG server during FOG service startup. If the communication module fails to connect, the taskReboot and HostnameChanger module fail to do their job, because they use the encrypted channel if I’m not mistaken.
We can work around this problem by restarting to FOG service a few minutes after the windows 8.1 client is powered on.
This causes big problems during deployment because the FOG client handles the hostname changing and active directory joining.Any ideas?
fog.log right after system startup:
30/11/2015 12:24 Bus Became bus server 30/11/2015 12:24 Bus { "channel": "Status", "data": "{\r\n \"action\": \"load\"\r\n}" } 30/11/2015 12:24 Bus Emmiting message on channel: Status ------------------------------------------------------------------------------ --------------------------------Authentication-------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:24 Client-Info Version: 0.9.7 30/11/2015 12:24 Middleware::Communication URL: http://192.168.129.12/fog/management/other/ssl/srvpublic.crt 30/11/2015 12:24 Middleware::Communication ERROR: Could not download file 30/11/2015 12:24 Middleware::Communication ERROR: Kan geen verbinding met de externe server maken 30/11/2015 12:24 Middleware::Authentication ERROR: Could not authenticate 30/11/2015 12:24 Middleware::Authentication ERROR: Het systeem kan het opgegeven bestand niet vinden. 30/11/2015 12:24 Bus Registering ParseBus in channel Power ------------------------------------------------------------------------------ ---------------------------------ClientUpdater-------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:24 Client-Info Version: 0.9.7 30/11/2015 12:24 ClientUpdater Running... 30/11/2015 12:24 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=clientupdater&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:24 Middleware::Communication ERROR: Could not contact FOG server 30/11/2015 12:24 Middleware::Communication ERROR: Kan geen verbinding met de externe server maken ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ----------------------------------TaskReboot---------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:24 Client-Info Version: 0.9.7 30/11/2015 12:24 TaskReboot Running... 30/11/2015 12:24 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=taskreboot&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:24 Middleware::Communication ERROR: Could not contact FOG server 30/11/2015 12:24 Middleware::Communication ERROR: Kan geen verbinding met de externe server maken ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ --------------------------------HostnameChanger------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:24 Client-Info Version: 0.9.7 30/11/2015 12:24 HostnameChanger Running... 30/11/2015 12:24 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=hostnamechanger&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:24 Middleware::Communication ERROR: Could not contact FOG server 30/11/2015 12:24 Middleware::Communication ERROR: Kan geen verbinding met de externe server maken ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ---------------------------------SnapinClient--------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:24 Client-Info Version: 0.9.7 30/11/2015 12:24 SnapinClient Running... 30/11/2015 12:24 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=snapinclient&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:24 Middleware::Communication ERROR: Could not contact FOG server 30/11/2015 12:24 Middleware::Communication ERROR: Kan geen verbinding met de externe server maken ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ --------------------------------PrinterManager-------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:24 Client-Info Version: 0.9.7 30/11/2015 12:24 PrinterManager Running... 30/11/2015 12:24 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=printermanager&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:24 Middleware::Communication ERROR: Could not contact FOG server 30/11/2015 12:24 Middleware::Communication ERROR: Kan geen verbinding met de externe server maken ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ -----------------------------------GreenFOG----------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:24 Client-Info Version: 0.9.7 30/11/2015 12:24 GreenFOG Running... 30/11/2015 12:24 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=greenfog&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:24 Middleware::Communication ERROR: Could not contact FOG server 30/11/2015 12:24 Middleware::Communication ERROR: Kan geen verbinding met de externe server maken ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ----------------------------------UserTracker--------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:24 Client-Info Version: 0.9.7 30/11/2015 12:24 UserTracker Running... 30/11/2015 12:24 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=usertracker&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:24 Middleware::Communication ERROR: Could not contact FOG server 30/11/2015 12:24 Middleware::Communication ERROR: Kan geen verbinding met de externe server maken ------------------------------------------------------------------------------ 30/11/2015 12:24 Middleware::Communication URL: http://192.168.129.12/fog/management/index.php?node=client&sub=configure&newService=1 30/11/2015 12:24 Middleware::Communication ERROR: Could not contact FOG server 30/11/2015 12:24 Middleware::Communication ERROR: Kan geen verbinding met de externe server maken 30/11/2015 12:24 Service Sleeping for 60 seconds ------------------------------------------------------------------------------ ---------------------------------ClientUpdater-------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:25 Client-Info Version: 0.9.7 30/11/2015 12:25 ClientUpdater Running... 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=clientupdater&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:25 Middleware::Communication Response: Success 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/getversion.php?client&newService=1 ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ----------------------------------TaskReboot---------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:25 Client-Info Version: 0.9.7 30/11/2015 12:25 TaskReboot Running... 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=taskreboot&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:25 Middleware::Communication Response: Success 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/jobs.php?mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:25 Middleware::Communication Unknown Response: ?h*?????[??N? ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ --------------------------------HostnameChanger------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:25 Client-Info Version: 0.9.7 30/11/2015 12:25 HostnameChanger Running... 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=hostnamechanger&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:25 Middleware::Communication Response: Success 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/hostname.php?moduleid=hostnamechanger&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:25 Middleware::Communication Unknown Response: }U???y??`??b???])nR?rVAZ"?%2`?5????à???'?r???@????&{??m??5Z?Mm??D:}?;$???_???mpc#d$Oy??4+?????ot???G??g0????S? ??S<&??:??{?Dt ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ---------------------------------SnapinClient--------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:25 Client-Info Version: 0.9.7 30/11/2015 12:25 SnapinClient Running... 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=snapinclient&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:25 Middleware::Communication Response: Success 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/snapins.checkin.php?mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:25 Middleware::Communication Response: No snapins ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ --------------------------------PrinterManager-------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:25 Client-Info Version: 0.9.7 30/11/2015 12:25 PrinterManager Running... 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=printermanager&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:25 Middleware::Communication Response: Module is disabled globally on the FOG server ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ -----------------------------------GreenFOG----------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:25 Client-Info Version: 0.9.7 30/11/2015 12:25 GreenFOG Running... 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=greenfog&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:25 Middleware::Communication Response: Module is disabled globally on the FOG server ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ----------------------------------UserTracker--------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:25 Client-Info Version: 0.9.7 30/11/2015 12:25 UserTracker Running... 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=usertracker&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:25 Middleware::Communication Response: Success ------------------------------------------------------------------------------ 30/11/2015 12:25 Middleware::Communication URL: http://192.168.129.12/fog/management/index.php?node=client&sub=configure&newService=1 30/11/2015 12:25 Middleware::Communication Response: Success 30/11/2015 12:25 Service Sleeping for 93 seconds
fog.log after FOGservice restart when the client is already powered on for a while
30/11/2015 12:18 Bus Became bus server 30/11/2015 12:18 Bus { "channel": "Status", "data": "{\r\n \"action\": \"load\"\r\n}" } 30/11/2015 12:18 Bus Emmiting message on channel: Status ------------------------------------------------------------------------------ --------------------------------Authentication-------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:18 Client-Info Version: 0.9.7 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/management/other/ssl/srvpublic.crt 30/11/2015 12:18 Data::RSA FOG Server CA cert found 30/11/2015 12:18 Middleware::Authentication Cert OK 30/11/2015 12:18 Middleware::Communication POST URL: http://192.168.129.12/fog/management/index.php?sub=authorize 30/11/2015 12:18 Middleware::Communication Response: Success 30/11/2015 12:18 Middleware::Authentication Authenticated 30/11/2015 12:18 Bus Registering ParseBus in channel Power ------------------------------------------------------------------------------ ---------------------------------ClientUpdater-------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:18 Client-Info Version: 0.9.7 30/11/2015 12:18 ClientUpdater Running... 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=clientupdater&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:18 Middleware::Communication Response: Success 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/getversion.php?client&newService=1 ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ----------------------------------TaskReboot---------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:18 Client-Info Version: 0.9.7 30/11/2015 12:18 TaskReboot Running... 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=taskreboot&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:18 Middleware::Communication Response: Success 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/jobs.php?mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:18 Middleware::Communication Response: No jobs ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ --------------------------------HostnameChanger------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:18 Client-Info Version: 0.9.7 30/11/2015 12:18 HostnameChanger Running... 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=hostnamechanger&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:18 Middleware::Communication Response: Success 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/hostname.php?moduleid=hostnamechanger&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:18 Middleware::Communication Response: Success 30/11/2015 12:18 HostnameChanger Checking Hostname 30/11/2015 12:18 HostnameChanger Hostname is correct 30/11/2015 12:18 HostnameChanger Registering host with active directory 30/11/2015 12:18 HostnameChanger Host is already joined to target domain 30/11/2015 12:18 HostnameChanger Activing host with product key ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ---------------------------------SnapinClient--------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:18 Client-Info Version: 0.9.7 30/11/2015 12:18 SnapinClient Running... 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=snapinclient&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:18 Middleware::Communication Response: Success 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/snapins.checkin.php?mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:18 Middleware::Communication Response: No snapins ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ --------------------------------PrinterManager-------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:18 Client-Info Version: 0.9.7 30/11/2015 12:18 PrinterManager Running... 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=printermanager&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:18 Middleware::Communication Response: Module is disabled globally on the FOG server ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ -----------------------------------GreenFOG----------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:18 Client-Info Version: 0.9.7 30/11/2015 12:18 GreenFOG Running... 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=greenfog&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:18 Middleware::Communication Response: Module is disabled globally on the FOG server ------------------------------------------------------------------------------ ------------------------------------------------------------------------------ ----------------------------------UserTracker--------------------------------- ------------------------------------------------------------------------------ 30/11/2015 12:18 Client-Info Version: 0.9.7 30/11/2015 12:18 UserTracker Running... 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/servicemodule-active.php?moduleid=usertracker&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 30/11/2015 12:18 Middleware::Communication Response: Success 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/service/usertracking.report.php?action=login&user=TEST380\Administrator&mac=00:25:64:A3:9B:22||00:00:00:00:00:00:00:E0&newService=1 ------------------------------------------------------------------------------ 30/11/2015 12:18 Middleware::Communication URL: http://192.168.129.12/fog/management/index.php?node=client&sub=configure&newService=1 30/11/2015 12:18 Middleware::Communication Response: Success 30/11/2015 12:18 Service Sleeping for 77 seconds
-
When you have the “Could not contact” can you get the apache error logs?
-
Nothing shows up in the apache error logs, because the FOGservice is not connecting to the FOG server (I’ve just checked the apache error log).
I think the problem is that the FOG service starts up too fast. It’s already running when the network interface initialization hasn’t been completed yet in Windows.I’ve now configured the FOG service to startup delayed. This resolves the issue!
A better solution should be that the Authentication module would run each time the FOGservice checks in and not only during FOGservice startup.
An even better solution should be that FOGservice checks if the Windows network interface has a valid IP address before executing all the modules.
-
@zavo the authentication does recheck when it needs to, not more often than that though. Why? Simple, security.
-
@zavo , the problem is that the server still has an active encryption session from last boot, so re-authentication is not running. I’ll push a patch in a couple days (I need to ensure it won’t accidentally denial of service the server if there are errors on the server side).
-
@zavo Thank you so much for reporting this. While working on this bug, I came across the reason why I was never able to get my v0.10 builds running on Windows! It was a problem with the authentication handshake stalling the Windows Service Controller. I’m currently re-designing how/when authentication happens in the client and will retrofit the patch onto v0.9.X shortly.
This patch will also prevent the service from killing VM network connections for the first few minutes after windows starts.
-
@zavo v0.9.8 released. This should correct this issue. Can you confirm when you have a chance?
-
@Jbob I confirm the problem has been resolved! Thnx a lot for the fix, keep up the good work!