FOG Client log reporting old RC and odd behavior

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

0_1477946515907_upload-993bda22-e762-477b-bbe9-a5edb66b24b7

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

Wayne Workman

@Tom-Elliott I know how the search works, it’s very robust and useful. However I’ve looked through this host’s groups, inventory, snapins, printers. I can’t find any string with “r01300” in it in any of those areas for that host. I don’t know why it’s matching - and I think it odd that it also happened to suffer from the OP’s bug.

Tom Elliott

@Wayne-Workman My description of elements searches was even further limited that how much is searched. If the string r01300 shows up in any of the inventory and what not. It’s difficult to express what and/or where, but I can try a session tonight with you if you’re up to it to see if we can figure out exactly where this is all occurring.

Wayne Workman

Just wanted to post an update here, Joe has been helping me with figuring out what the problem is, he built a special copy of the fog client for me to use, and I’ve been using this along with some other scripting techniques to try to “cause” the issue to happen, and when it does this special fog client has mechanisms in it to immediately gather data that we need to figure out what’s happening.

So… it’s just a waiting game right now.

fry_p

@Wayne-Workman I have the utmost confidence in the team. I patiently await the results.

Wayne Workman

@fry_p We need to compare windows updates with each other.
Control Panel -> Small Icons -> Programs and Features -> View Installed Updates

Here’s mine, post yours too please from a system that was affected.

0_1478196700935_upload-bbf21eb8-369f-4ea1-93d5-6cb1ac1794b5

fry_p

@Wayne-Workman there are quite a few more updates on my side. I exported a nice html list of them but am unable to upload anything besides a picture to the forums. The list is too long for a screenshot. I have a csv of them also. Let me know how to proceed.

Wayne Workman

@fry_p Can you look at my list and see if you have any of those installed?

fry_p

@Wayne-Workman

I have none of the KB Windows updates, no flash player update, and my acrobat reader DC update version is 15.020.20039.

Wayne Workman

@fry_p Is your environment all Windows 7 pro? My environment is Windows 10 Enterprise LTSB x64.

FOG Client log reporting old RC and odd behavior

203

12.0k

17.3k

155.2k