FOG Client log reporting old RC and odd behavior

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

[Wayne Workman]

@Senior-Developers I might have found a clue. One of the earlier systems I pulled the blank settings.json file from, I didn’t notice then but now I notice.

Look at it’s name in fog? Look at my search criteria. I’m searching by room number (first 6 characters of name) and then doing a sub-search for windows desktop mb (my building abbreviation).

How did that computer show up in the search results?? And that computer just so happens to be one of the systems with this bug… The MAC address from the previous log I posted matches it’s mac. 90:B1:1C:98:08:81

[Wayne Workman]

I have a host ID of zero.

MariaDB [fog]> SELECT `hostID`, `hostName` FROM `hosts` WHERE `hostID` = '0';
+--------+----------+
| hostID | hostName |
+--------+----------+
|      0 |          |
+--------+----------+
1 row in set (0.00 sec)

Information about that host:

SELECT * FROM `hosts` WHERE `hostID` NOT IN (SELECT `hmhostID` FROM `hostMAC`);
+--------+-----------------+--------------------------------------------------+------------+-----------+--------------+---------------------+---------------------+--------------+-----------+--------------+----------+------------+------------+------------------+----------------+------------------+----------------+------------+------------+----------+-------------+------------+--------------+---------------------+--------------+--------------+-------------+-------------+
| hostID | hostName        | hostDesc                                         | hostIP     | hostImage | hostBuilding | hostCreateDate      | hostLastDeploy      | hostCreateBy | hostUseAD | hostADDomain | hostADOU | hostADUser | hostADPass | hostADPassLegacy | hostProductKey | hostPrinterLevel | hostKernelArgs | hostKernel | hostDevice | hostInit | hostPending | hostPubKey | hostSecToken | hostSecTime         | hostPingCode | hostExitBios | hostExitEfi | hostEnforce |
+--------+-----------------+--------------------------------------------------+------------+-----------+--------------+---------------------+---------------------+--------------+-----------+--------------+----------+------------+------------+------------------+----------------+------------------+----------------+------------+------------+----------+-------------+------------+--------------+---------------------+--------------+--------------+-------------+-------------+
|      0 |                 |                                                  |            |         0 |            0 | 2016-10-25 18:15:40 | 0000-00-00 00:00:00 | fog          |           |              |          |            |            |                  |                |                  |                |            |            |          |             |            |              | 0000-00-00 00:00:00 |              |              |             |             |
|    826 | R01100ROBOTWLMB | Created by FOG Reg on January 15, 2016, 11:04 am | 10.2.3.253 |         1 |            0 | 2016-01-15 11:04:52 | 0000-00-00 00:00:00 | fog          |           |              |          |            |            |                  |                |                  |                |            |            | NULL     |             |            |              | 0000-00-00 00:00:00 | 110          |              |             | 1           |
+--------+-----------------+--------------------------------------------------+------------+-----------+--------------+---------------------+---------------------+--------------+-----------+--------------+----------+------------+------------+------------------+----------------+------------------+----------------+------------+------------+----------+-------------+------------+--------------+---------------------+--------------+--------------+-------------+-------------+
2 rows in set (0.01 sec)

And it has several snapins assigned to it.

MariaDB [fog]> SELECT * from `snapinAssoc` WHERE `saID` = '0' OR `saHostID` = '0' OR `saSnapinID` = '0';
+------+----------+------------+
| saID | saHostID | saSnapinID |
+------+----------+------------+
| 7037 |        0 |         38 |
| 7031 |        0 |         19 |
| 7028 |        0 |         31 |
| 7032 |        0 |         20 |
| 7035 |        0 |         32 |
| 7034 |        0 |         30 |
| 7033 |        0 |         23 |
| 7036 |        0 |         34 |
+------+----------+------------+
8 rows in set (0.00 sec)

[Wayne Workman]

Even after deleting all those junk entries in the DB, that one computer that did have the bug still incorrectly shows up in the search results.

[Tom Elliott]

@Wayne-Workman incorrectly shows up? The search at first searches for multiple Ares. If r01300 is group the host is in, a snapin, an image, description, etc… It will show in the list. Fog isn’t just searching data on one field.