FOG Client log reporting old RC and odd behavior

[Wayne Workman]

@fry_p Is there a bunch of white space inside of settings.json? Mine wasn’t just totally blank but had a bunch of spaces in it.

[Joe Schmitt]

@fry_p I can push out a band-aid in a few hours that’ll prevent any more clients from loosing their settings file. We still need to find out the underlying server issue, but this patch will stop any more damage from being done.

[Wayne Workman]

@Joe-Schmitt How easy would it be to gather every GUID for every version of the new fog client?

[Joe Schmitt]

@Wayne-Workman Why?

[Wayne Workman]

@fry_p This particular computer you pulled the log from in the opening post, is it configured to sleep after a specified time of inactivity? Either through settings you put on the image it uses or via GPO? If so, what is that time length set to?

[Joe Schmitt]

@fry_p could you upload a copy of the blanked setting files along with a hexdump of it?

[fry_p]

@Wayne-Workman @Joe-Schmitt They are configured to never go to sleep or hibernate through group policy. Give me a moment for the settings file.

[fry_p]

@Joe-Schmitt

It says I don’t have enough privileges to upload to the forums.

[Joe Schmitt]

Odd. Could you still include the hexdump? Really that’s all I need.

[fry_p]

@Joe-Schmitt not much to see, flagged it as spam when I tried to copy paste it.

[Joe Schmitt]

@fry_p so that’s not good. The entire file is getting zero’d out.

[Wayne Workman]

So I’ve been thinking about lots of ways to try to detect when this happens.

The best idea I’ve had so far is to have a login script via GPO just copy each computer’s settings.json file to a share on the fog server, and have the fog server run a script every hour via CRON to do a checksum on every file, and then if any match the signature of one of the blank files, to just log it. This would give me a list of computers with the problem.

[Wayne Workman]

@Joe-Schmitt here is a copy of the file.

0_1477940167270_settings.json

The computer this file came from hasn’t been imaged in a long while, but we’ve tried deploying snapins to update things like Chrome several times, and also I sometimes deploy snapins with batch files for various things.

Here’s the log file. Joe, look at the end of the log.
0_1477940491375_fog.log

The log says that the client stopped working at 9/7/2016 4:50 PM

The teacher that uses this room says she’s only in here on Mondays and Wednesdays, and September 7th was a Wednesday. Maybe it’s coincidence, maybe the bug is somehow/someway related to being used or after being used.

Looking through the system logs, the Meraki service we have installed on all our systems is crashing a lot.

@fry_p do you have Meraki installed?

[Joe Schmitt]

@Wayne-Workman now that is very interesting. The Log API uses a different style of file writing than the Settings API does. So the fact that this is somehow happening to both is very surprising. I suspect some kind of outside interference.

[Joe Schmitt]

@fry_p could you upload the log file of a host that has stopped functioning?

If you still can’t upload provide a hex dump in a code block, e.g.

....
....

If I’m right you should have a large amount of null bytes at the end of the file.

[Wayne Workman]

@Joe-Schmitt Here’s somethin else kind of interesting.

Right now I’m sitting in front of another computer that never returned for the “roll-call” if you remember when I did that.

Here’s it’s c:\users\tech.fog_user file.
0_1477944159340_.fog_user.log

Notice, the log times… This computer went unused for a month !?!

------------------------------------------------------------------------------
--------------------------------DisplayManager--------------------------------
------------------------------------------------------------------------------
 9/30/2016 2:59 PM Client-Info Client Version: 0.11.5
 9/30/2016 2:59 PM Client-Info Client OS:      Windows
 9/30/2016 2:59 PM Client-Info Server Version: 1.3.0-RC-10
 9/30/2016 2:59 PM Middleware::Response Success
 9/30/2016 2:59 PM DisplayManager ERROR: Invalid settings provided
------------------------------------------------------------------------------

 9/30/2016 2:59 PM Service Sleeping for 44 seconds
 10/31/2016 2:58 PM UserService Initializing - phase 1
 10/31/2016 2:58 PM Bus Registering ParseBus in channel Power
 10/31/2016 2:58 PM UserService Initializing - phase 2
 10/31/2016 2:58 PM Zazzles Creating main thread
 10/31/2016 2:58 PM Zazzles Service construction complete

 10/31/2016 2:58 PM Service Starting service
 10/31/2016 2:58 PM Bus Became bus client
 10/31/2016 2:58 PM Bus Registering OnUpdate in channel Update
 10/31/2016 2:58 PM Bus Registering OnPower in channel Power
 10/31/2016 2:58 PM Bus Registering OnStatus in channel Status

 10/31/2016 2:58 PM Middleware::Response Success
 10/31/2016 2:58 PM Service Initializing modules

------------------------------------------------------------------------------
----------------------------------AutoLogOut----------------------------------
------------------------------------------------------------------------------
 10/31/2016 2:58 PM Client-Info Client Version: 0.11.5
 10/31/2016 2:58 PM Client-Info Client OS:      Windows
 10/31/2016 2:58 PM Client-Info Server Version: 1.3.0-RC-17
 10/31/2016 2:58 PM Middleware::Response Success
------------------------------------------------------------------------------


------------------------------------------------------------------------------
-----------------------------DefaultPrinterManager----------------------------
------------------------------------------------------------------------------
 10/31/2016 2:58 PM Client-Info Client Version: 0.11.5
 10/31/2016 2:58 PM Client-Info Client OS:      Windows
 10/31/2016 2:58 PM Client-Info Server Version: 1.3.0-RC-17
 10/31/2016 2:58 PM Middleware::Response Success
 10/31/2016 2:58 PM DefaultPrinterManager Checking defaults
 10/31/2016 2:58 PM Printer Setting Ed Options Lab as default
 10/31/2016 2:58 PM PrinterManager PrintUI return code = 0
------------------------------------------------------------------------------


------------------------------------------------------------------------------
--------------------------------DisplayManager--------------------------------
------------------------------------------------------------------------------
 10/31/2016 2:58 PM Client-Info Client Version: 0.11.5
 10/31/2016 2:58 PM Client-Info Client OS:      Windows
 10/31/2016 2:58 PM Client-Info Server Version: 1.3.0-RC-17
 10/31/2016 2:58 PM Middleware::Response Success
 10/31/2016 2:58 PM DisplayManager ERROR: Invalid settings provided
------------------------------------------------------------------------------

 10/31/2016 2:58 PM Service Sleeping for 90 seconds
 10/31/2016 2:58 PM Bus::Client ERROR: No connection could be made because the target machine actively refused it
 10/31/2016 2:58 PM Bus::Client ERROR: Connection lost
 10/31/2016 2:59 PM Bus::Client ERROR: No connection could be made because the target machine actively refused it
 10/31/2016 2:59 PM Bus::Client ERROR: No connection could be made because the target machine actively refused it

Notice also, those errors at the bottom (above this text) are EXACTLY the same ones I found and reported in the other thread. Here is the fog.log file, the client will not write to it.

0_1477944321065_fog.log

For the moment, the settings.json file has this - and it’s inaccurate. We are on RC-18, not 17.

{
  "HTTPS": "0",
  "Tray": "1",
  "Server": "10.2.1.11",
  "WebRoot": "/fog",
  "Version": "0.11.5",
  "Company": "FOG",
  "RootLog": "1",
  "ServerVersion": "1.3.0-RC-17",
  "ALOTime": "",
  "DefaultPrinter": "Ed Options Lab",
  "DisplayX": "",
  "DisplayY": "",
  "DisplayR": "",
  "PromptTime": "60",
  "Sleep": "90"
}

@Joe-Schmitt I think I found a computer that is soon to destroy it’s settings.json file?

[Joe Schmitt]

@Wayne-Workman I am genuinely at a loss of ideas right now. @Developers if anyone’s got any theories I’d be happy to hear them. As of right now my best guess is perhaps some kind of interference from another process.

Notice, the log times… from 2:59 -> 2:58 -> 2:59.

The client grabs the time straight from the SYSTEM itself. The only thing I can think of is some other program / script / policy is managing parts of the computer.

[Wayne Workman]

Just for reference, here’s a snippet of the .fog_user.log file from the other thread here:
https://forums.fogproject.org/topic/8819/fog-client-stops-reporting-working

------------------------------------------------------------------------------
--------------------------------DisplayManager--------------------------------
------------------------------------------------------------------------------
 10/19/2016 3:24 PM Client-Info Client Version: 0.11.5
 10/19/2016 3:24 PM Client-Info Client OS:      Windows
 10/19/2016 3:24 PM Client-Info Server Version: 1.3.0-RC-14
 10/19/2016 3:24 PM Middleware::Response Success
 10/19/2016 3:24 PM DisplayManager ERROR: Invalid settings provided
------------------------------------------------------------------------------

 10/19/2016 3:24 PM Service Sleeping for 118 seconds
 10/20/2016 6:50 AM UserService Initializing - phase 1
 10/20/2016 6:50 AM Bus Registering ParseBus in channel Power
 10/20/2016 6:50 AM Middleware::Configuration ERROR: Invalid parameters
 10/20/2016 6:50 AM UserService Initializing - phase 2
 10/20/2016 6:50 AM Zazzles Creating main thread
 10/20/2016 6:50 AM Zazzles Service construction complete

 10/20/2016 6:50 AM Service Starting service
 10/20/2016 6:50 AM Service ERROR: ServerAddress not found! Exiting.
 10/24/2016 6:53 AM UserService Initializing - phase 1
 10/24/2016 6:53 AM Bus Registering ParseBus in channel Power
 10/24/2016 6:53 AM Middleware::Configuration ERROR: Invalid parameters
 10/24/2016 6:53 AM UserService Initializing - phase 2
 10/24/2016 6:53 AM Zazzles Creating main thread
 10/24/2016 6:53 AM Zazzles Service construction complete

 10/24/2016 6:53 AM Service Starting service
 10/24/2016 6:53 AM Service ERROR: ServerAddress not found! Exiting.

@Joe-Schmitt Notice the log dates and times! It jumps dates! Just like what I posted below!

[Wayne Workman]

9/30/2016 2:59 PM Service Sleeping for 44 seconds
10/31/2016 2:58 PM UserService Initializing - phase 1

That wasn’t 44 seconds.

 10/19/2016 3:24 PM Service Sleeping for 118 seconds
 10/20/2016 6:50 AM UserService Initializing - phase 1

And that was no 118 seconds.

[Joe Schmitt]

@Wayne-Workman

 10/19/2016 3:24 PM Service Sleeping for 118 seconds
 10/20/2016 6:50 AM UserService Initializing - phase 1

User logs are prone to that. They don’t log the exiting sequence. So what happened is while it was sleeping the person logged out. And at 6:50AM the person logged back in. The issue here is the client is writing null bytes to files.