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
    


  • @Jbob I confirm the problem has been resolved! Thnx a lot for the fix, keep up the good work!


  • Senior Developer

    @zavo v0.9.8 released. This should correct this issue. Can you confirm when you have a chance?


  • Senior Developer

    @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.


  • Senior Developer

    @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).

    https://github.com/FOGProject/fog-client/issues/32


  • Senior Developer

    @zavo the authentication does recheck when it needs to, not more often than that though. Why? Simple, security.



  • 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.


  • Senior Developer

    When you have the “Could not contact” can you get the apache error logs?


Log in to reply
 

411
Online

39.3k
Users

11.0k
Topics

104.6k
Posts

Looks like your connection to FOG Project was lost, please wait while we try to reconnect.