FOG Client log reporting old RC and odd behavior

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

[fry_p]

@Joe-Schmitt This is the very end of the log in question in hex (no permissions to upload the file and too many lines for the full dump in the code window).

0003B040  20 31 31 3A 34 32 20 41 4D 20 43 6C 69 65 6E 74   11:42 AM Client
0003B050  2D 49 6E 66 6F 20 43 6C 69 65 6E 74 20 56 65 72  -Info Client Ver
0003B060  73 69 6F 6E 3A 20 30 2E 31 31 2E 35 0D 0A 20 39  sion: 0.11.5.. 9
0003B070  2F 31 35 2F 32 30 31 36 20 31 31 3A 34 32 20 41  /15/2016 11:42 A
0003B080  4D 20 43 6C 69 65 6E 74 2D 49 6E 66 6F 20 43 6C  M Client-Info Cl
0003B090  69 65 6E 74 20 4F 53 3A 20 20 20 20 20 20 57 69  ient OS:      Wi
0003B0A0  6E 64 6F 77 73 0D 0A 20 39 2F 31 35 2F 32 30 31  ndows.. 9/15/201
0003B0B0  36 20 31 31 3A 34 32 20 41 4D 20 43 6C 69 65 6E  6 11:42 AM Clien
0003B0C0  74 2D 49 6E 66 6F 20 53 65 72 76 65 72 20 56 65  t-Info Server Ve
0003B0D0  72 73 69 6F 6E 3A 20 31 2E 33 2E 30 2D 52 43 2D  rsion: 1.3.0-RC-
0003B0E0  31 30 0D 0A 20 39 2F 31 35 2F 32 30 31 36 20 31  10.. 9/15/2016 1
0003B0F0  31 3A 34 32 20 41 4D 20 4D 69 64 64 6C 65 77 61  1:42 AM Middlewa
0003B100  72 65 3A 3A 52 65 73 70 6F 6E 73 65 20 53 75 63  re::Response Suc
0003B110  63 65 73 73 0D 0A 20 39 2F 31 35 2F 32 30 31 36  cess.. 9/15/2016
0003B120  20 31 31 3A 34 32 20 41 4D 20 50 6F 77 65 72 4D   11:42 AM PowerM
0003B130  61 6E 61 67 65 6D 65 6E 74 20 43 61 6C 63 75 6C  anagement Calcul
0003B140  61 74 69 6E 67 20 74 61 73 6B 73 20 74 6F 20 75  ating tasks to u
0003B150  6E 73 63 68 65 64 75 6C 65 0D 0A 20 39 2F 31 35  nschedule.. 9/15
0003B160  2F 32 30 31 36 20 31 31 3A 34 32 20 41 4D 20 50  /2016 11:42 AM P
0003B170  6F 77 65 72 4D 61 6E 61 67 65 6D 65 6E 74 20 43  owerManagement C
0003B180  61 6C 63 75 6C 61 74 69 6E 67 20 74 61 73 6B 73  alculating tasks
0003B190  20 74 6F 20 73 63 68 65 64 75 6C 65 0D 0A 2D 2D   to schedule..--
0003B1A0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B1B0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B1C0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B1D0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B1E0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 0D 0A 0D 0A  ------------....
0003B1F0  0D 0A 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ..--------------
0003B200  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B210  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B220  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B230  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B240  0D 0A 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ..--------------
0003B250  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B260  2D 2D 2D 2D 55 73 65 72 54 72 61 63 6B 65 72 2D  ----UserTracker-
0003B270  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B280  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B290  0D 0A 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ..--------------
0003B2A0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B2B0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B2C0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B2D0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B2E0  0D 0A 20 39 2F 31 35 2F 32 30 31 36 20 31 31 3A  .. 9/15/2016 11:
0003B2F0  34 32 20 41 4D 20 43 6C 69 65 6E 74 2D 49 6E 66  42 AM Client-Inf
0003B300  6F 20 43 6C 69 65 6E 74 20 56 65 72 73 69 6F 6E  o Client Version
0003B310  3A 20 30 2E 31 31 2E 35 0D 0A 20 39 2F 31 35 2F  : 0.11.5.. 9/15/
0003B320  32 30 31 36 20 31 31 3A 34 32 20 41 4D 20 43 6C  2016 11:42 AM Cl
0003B330  69 65 6E 74 2D 49 6E 66 6F 20 43 6C 69 65 6E 74  ient-Info Client
0003B340  20 4F 53 3A 20 20 20 20 20 20 57 69 6E 64 6F 77   OS:      Window
0003B350  73 0D 0A 20 39 2F 31 35 2F 32 30 31 36 20 31 31  s.. 9/15/2016 11
0003B360  3A 34 32 20 41 4D 20 43 6C 69 65 6E 74 2D 49 6E  :42 AM Client-In
0003B370  66 6F 20 53 65 72 76 65 72 20 56 65 72 73 69 6F  fo Server Versio
0003B380  6E 3A 20 31 2E 33 2E 30 2D 52 43 2D 31 30 0D 0A  n: 1.3.0-RC-10..
0003B390  20 39 2F 31 35 2F 32 30 31 36 20 31 31 3A 34 32   9/15/2016 11:42
0003B3A0  20 41 4D 20 4D 69 64 64 6C 65 77 61 72 65 3A 3A   AM Middleware::
0003B3B0  52 65 73 70 6F 6E 73 65 20 53 75 63 63 65 73 73  Response Success
0003B3C0  0D 0A 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ..--------------
0003B3D0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B3E0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B3F0  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B400  2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D 2D  ----------------
0003B410  0D 0A 0D 0A 20 39 2F 31 35 2F 32 30 31 36 20 31  .... 9/15/2016 1
0003B420  31 3A 34 32 20 41 4D 20 4D 69 64 64 6C 65 77 61  1:42 AM Middlewa
0003B430  72 65 3A 3A 43 6F 6D 6D 75 6E 69 63 61 74 69 6F  re::Communicatio
0003B440  6E 20 55 52 4C 3A 20 68 74 74 70 3A 2F 2F 31 30  n URL: http://10
0003B450  2E 31 2E 31 30 36 2E 31 36 39 2F 66 6F 67 2F 6D  .1.106.169/fog/m
0003B460  61 6E 61 67 65 6D 65 6E 74 2F 69 6E 64 65 78 2E  anagement/index.
0003B470  70 68 70 3F 73 75 62 3D 72 65 71 75 65 73 74 43  php?sub=requestC
0003B480  6C 69 65 6E 74 49 6E 66 6F 26 63 6F 6E 66 69 67  lientInfo&config
0003B490  75 72 65 26 6E 65 77 53 65 72 76 69 63 65 26 6A  ure&newService&j
0003B4A0  73 6F 6E 0D 0A 20 39 2F 31 35 2F 32 30 31 36 20  son.. 9/15/2016 
0003B4B0  31 31 3A 34 32 20 41 4D 20 4D 69 64 64 6C 65 77  11:42 AM Middlew
0003B4C0  61 72 65 3A 3A 52 65 73 70 6F 6E 73 65 20 53 75  are::Response Su
0003B4D0  63 63 65 73 73 0D 0A 20 39 2F 31 35 2F 32 30 31  ccess.. 9/15/201
0003B4E0  36 20 31 31 3A 34 32 20 41 4D 20 53 65 72 76 69  6 11:42 AM Servi
0003B4F0  63 65 20 45 52 52 4F 52 3A 20 49 6E 76 61 6C 69  ce ERROR: Invali
0003B500  64 20 70 72 6F 6D 70 74 54 69 6D 65 2C 20 75 73  d promptTime, us
0003B510  69 6E 67 20 64 65 66 61 75 6C 74 0D 0A 20 39 2F  ing default.. 9/
0003B520  31 35 2F 32 30 31 36 20 31 31 3A 34 32 20 41 4D  15/2016 11:42 AM
0003B530  20 53 65 72 76 69 63 65 20 53 6C 65 65 70 69 6E   Service Sleepin
0003B540  67 20 66 6F 72 20 31 32 38 20 73 65 63 6F 6E 64  g for 128 second
0003B550  73 0D 0A                                         s..