This discussion has been locked.

You can no longer post new replies to this discussion. If you have a question you can start a new discussion

Most Clients Shown As 'Disconnected' in SEC 5.5.0

Hi folks,

We are running Sophos Enterprise Console (SEC) 5.5.0 on a Windows 2008 R2 Enterprise (64-bit) Server.

I have recently noticed that more than 50% of our client PCs to which Sophos Endpoint Security & Control has been deployed are shown as 'disconnected' in SEC. I have carried out a ping-sweep of the network and can confirm that most, if not all, of these PCs are actually powered on, connected to the network and working fine.

Only after I restart the Sophos Message Router Service on the client PCs do they then change their status to 'connected' in SEC. I have no wish to carry this task out on several hundred client PCs individually as you can imagine, so I'm hoping someone can possibly shed some light on what may be happening here and suggest a solution to this issue?

Many thanks,

John P

This thread was automatically locked due to age.

Parents

0 ruckus over 7 years ago

I'm sure there will be others offering advice, but from my experience, it's most likely that the Remote Management System (RMS) that cannot communicate on the required ports. You can try with the telnet command from the server to the endpoint and vice versa on the required ports.

You may like to watch the video below on setting up a GPO to allow the required ports (this means you don't have to go round to each computer). Watch from the 9 minute mark...

There is also the deployment guide which mentions the ports. http://www.sophos.com/deployment - click the 'Allowing computers to report' link on the right-hand rail.

- - - - - - - - - - - -

Communities Moderator, SOPHOS
Knowledge Base | @SophosSupport | Video tutorials
Remember to like a post. If a post (on a question thread) solves your question use the 'This helped me' link.
Cancel
Vote Up 0 Vote Down

Cancel

0 isoffice over 7 years ago in reply to ruckus

Hi guys,

Thank you for your prompt and helpful replies.

Christian, I have to admit that I may be a bit lax in checking my SEC installation. Unfortunately, my duties dictate that I cannot spend as much time as I'd like (or indeed, need) to monitor our SEC installation. Wearing too many hats at times methinks!!

Fullscreen Before and After Service ReStart.txt Download

19.09.2017 08:28:19 0B28 I SOF: C:\ProgramData/Sophos/Remote Management System/3/Router/Logs/Router-20170919-072819.log
19.09.2017 08:28:19 0B28 I Sophos Messaging Router 4.1.1.127 starting...
19.09.2017 08:28:19 0B28 I Setting ACE_FD_SETSIZE to 138
19.09.2017 08:28:19 0B28 I Initializing CORBA...
19.09.2017 08:28:19 0B28 I Connection cache limit is 10
19.09.2017 08:28:20 0B28 I Router::ConfigureSslContext: keeping legacy compatibility of TLS 1 and TLS 1.1.
19.09.2017 08:28:20 0B28 I Creating ORB runner with 4 threads
19.09.2017 08:28:20 0B28 I Compliant certificate hashing algorithm.
19.09.2017 08:28:20 0B28 I This computer is part of the domain SECRAT
19.09.2017 08:28:20 0B28 I This router's IOR:
IOR:010000002600000049444c3a536f70686f734d6573736167696e672f4d657373616765526f757465723a312e300000000100000000000000a0000000010102000a0000003132372e302e302e310001204100000014010f004e5550000000210000000001000000526f6f74504f4100526f7574657250657273697374656e740003000000010000004d657373616765526f7574657200000003000000000000000800000001000e01004f4154010000001800000001000e01010001000100000001000105090101000000000014000000080000000100a60086000220
19.09.2017 08:28:20 0B28 E Localhost address (e.g. 127/8) found in the IOR
19.09.2017 08:28:20 0B28 E This router's IOR is invalid
19.09.2017 08:28:20 0B28 I This computer is part of the domain ****
19.09.2017 08:28:20 0B28 I Reading router table file
19.09.2017 08:28:20 0B28 I Host name: DNIA16807
19.09.2017 08:28:20 0B28 I Local IP addresses: 10.63.14.118 
19.09.2017 08:28:20 0B28 I Resolved name: DNIA16807.****.****.****
19.09.2017 08:28:20 0B28 I Resolved alias/es: 
19.09.2017 08:28:20 0B28 I Resolved IP addresses: 127.0.0.1 
19.09.2017 08:28:20 0B28 I Resolved reverse names/aliases: DNIA16807.****.****.**** 
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01AE532F, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01AE8D1F, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01AFA2D6, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01AFDE91, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0B28 I Waiting for messages...
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01B0F5D5, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01B13019, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01B245FF, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01B28197, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01B63A35, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01B67608, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01B78F73, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01B7C79E, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01B8DE7B, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01B91916, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01BA3121, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01BA6A99, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01BB8324, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01BBBBFE, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01BF7130, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-GetStatus-Reply
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01BF7254, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01BF726D, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-GetStatus-Reply
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01BF9C9C, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-GetStatus-Reply
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01BFB08B, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:28:20 0CB8 I Routing to parent: id=01BFC6D0, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-GetStatus-Reply
19.09.2017 08:28:20 0CCC W Delivery failed(Timeout) for message type EM-GetStatus-Reply, originator Router$DNIA16807:450391.Agent
19.09.2017 08:28:20 0CCC W Delivery failed(Timeout) for message type EM-GetStatus-Reply, originator Router$DNIA16807:450391.Agent
19.09.2017 08:28:20 0CCC W Delivery failed(Timeout) for message type EM-GetStatus-Reply, originator Router$DNIA16807:450391.Agent
19.09.2017 08:28:20 0B28 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 3, max number of user ports 15360
19.09.2017 08:28:20 0CCC W Delivery failed(Timeout) for message type EM-GetStatus-Reply, originator Router$DNIA16807:450391.Agent
19.09.2017 08:28:22 0C94 I Client::LogonPushPush() successfully called back to client
19.09.2017 08:28:22 0C94 I Logged on Agent as a client
19.09.2017 08:28:22 0CB8 I Routing to Agent: id=03C0C716, origin=Router$DNIA16807:450391, dest=Router$DNIA16807:450391.Agent, type=EM-ClientLogon
19.09.2017 08:28:22 0CAC I Sent message (id=03C0C716) to Agent
19.09.2017 08:28:22 0CB8 I Received message for this router
19.09.2017 08:28:22 0CB8 I EM-NotifyClientUpdates originator Router$DNIA16807:450391.Agent
19.09.2017 08:28:22 0CB8 I Routing to Agent: id=07C0C716, origin=Router$DNIA16807:450391, dest=Router$DNIA16807:450391.Agent, type=EM-NotifyClientUpdates-Reply
19.09.2017 08:28:22 0CB0 I Sent message (id=07C0C716) to Agent
19.09.2017 08:28:57 0CB8 I Routing to parent: id=01C0C739, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-GetStatus-Reply
19.09.2017 08:33:48 0CB8 I Routing to parent: id=01C0C85C, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 08:34:10 0CCC W Delivery failed(Timeout) for message type EM-EntityEvent, originator Router$DNIA16807:450391.Agent
19.09.2017 08:34:14 0CB8 I Routing to parent: id=01C0C876, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-GetStatus-Reply
19.09.2017 09:28:20 0B28 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 5, max number of user ports 15360
19.09.2017 10:28:20 0B28 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 5, max number of user ports 15360
19.09.2017 11:28:21 0B28 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 5, max number of user ports 15360
19.09.2017 12:28:21 0B28 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 5, max number of user ports 15360
19.09.2017 12:40:21 0CCC W Delivery failed(Timeout) for message type EM-EntityEvent, originator Router$DNIA16807:450391.Agent
19.09.2017 12:40:50 0CB8 I Routing to parent: id=01C10242, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:28:21 0B28 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 5, max number of user ports 15360



19.09.2017 13:36:47 1AA4 I SOF: C:\ProgramData/Sophos/Remote Management System/3/Router/Logs/Router-20170919-123647.log
19.09.2017 13:36:47 1AA4 I Sophos Messaging Router 4.1.1.127 starting...
19.09.2017 13:36:47 1AA4 I Setting ACE_FD_SETSIZE to 138
19.09.2017 13:36:47 1AA4 I Initializing CORBA...
19.09.2017 13:36:47 1AA4 I Connection cache limit is 10
19.09.2017 13:36:48 1AA4 I Router::ConfigureSslContext: keeping legacy compatibility of TLS 1 and TLS 1.1.
19.09.2017 13:36:48 1AA4 I Creating ORB runner with 4 threads
19.09.2017 13:36:48 1AA4 I Compliant certificate hashing algorithm.
19.09.2017 13:36:48 1AA4 I This computer is part of the domain ****
19.09.2017 13:36:48 1AA4 I This router's IOR:
IOR:010000002600000049444c3a536f70686f734d6573736167696e672f4d657373616765526f757465723a312e300000000100000000000000a4000000010102000d00000031302e36332e31342e313138000001204100000014010f004e5550000000210000000001000000526f6f74504f4100526f7574657250657273697374656e740003000000010000004d657373616765526f7574657200000003000000000000000800000001001d01004f4154010000001800000001001d01010001000100000001000105090101000000000014000000080000000100a60086000220
19.09.2017 13:36:48 1AA4 I Successfully validated this router's IOR
19.09.2017 13:36:48 1AA4 I Reading router table file
19.09.2017 13:36:48 1AA4 I Host name: DNIA16807
19.09.2017 13:36:48 1AA4 I Local IP addresses: 10.63.14.118 
19.09.2017 13:36:48 1AA4 I Resolved name: DNIA16807.****.****.****
19.09.2017 13:36:48 1AA4 I Resolved alias/es: 
19.09.2017 13:36:48 1AA4 I Resolved IP addresses: 10.63.14.118 
19.09.2017 13:36:48 1AA4 I Resolved reverse names/aliases: DNIA16807.****.****.**** 
19.09.2017 13:36:48 1AA4 I Waiting for messages...
19.09.2017 13:36:48 1988 I Routing to parent: id=01AFA2D6, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1AA4 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 4, max number of user ports 15360
19.09.2017 13:36:48 1988 I Routing to parent: id=01AFDE91, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01B0F5D5, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01B13019, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01B245FF, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01B28197, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1B2C I Getting parent router IOR from 10.63.20.72:8192
19.09.2017 13:36:48 1988 I Routing to parent: id=01B63A35, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01B67608, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01B78F73, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01B7C79E, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01B8DE7B, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01B91916, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01BA3121, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01BA6A99, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01BB8324, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01BBBBFE, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01BF7254, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01BFB08B, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01C0C739, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-GetStatus-Reply
19.09.2017 13:36:48 1988 I Routing to parent: id=01C0C85C, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1988 I Routing to parent: id=01C0C876, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-GetStatus-Reply
19.09.2017 13:36:48 1988 I Routing to parent: id=01C10242, origin=Router$DNIA16807:450391.Agent, dest=EM, type=EM-EntityEvent
19.09.2017 13:36:48 1B2C I Received parent router's IOR:
IOR:010000002600000049444c3a536f70686f734d6573736167696e672f4d657373616765526f757465723a312e300000000100000000000000a4000000010102000c00000031302e36332e32302e3732004fc000004100000014010f004e5550000000210000000001000000526f6f74504f4100526f7574657250657273697374656e740003000000010000004d657373616765526f757465720000000300000000000000080000000100b700004f415401000000180000000100b700010001000100000001000105090101000000000014000000080000000100a60086000220
19.09.2017 13:36:48 1B2C I Successfully validated parent router's IOR
19.09.2017 13:36:48 1B2C I Accessing parent
19.09.2017 13:36:48 1B2C I SSL handshake done, local IP address = 10.63.14.118
19.09.2017 13:36:48 1B2C I Parent is Router$SV-AV-01
19.09.2017 13:36:48 1B2C I RouterTableEntry::LogonToParentRouter() - logging on as active consumer
19.09.2017 13:36:48 1B0C I SSL handshake done, local IP address = 10.63.14.118
19.09.2017 13:36:48 1B2C I RouterTableEntry state (router, logging on): Router$SV-AV-01 is passive consumer, passive supplier
19.09.2017 13:36:48 1B2C I Logged on to parent router as Router$DNIA16807:450391
19.09.2017 13:36:48 1B2C I This computer is part of the domain SECRAT
19.09.2017 13:36:48 1C14 I Sent message (id=01AFA2D6) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01AFDE91) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01B0F5D5) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01B13019) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01B245FF) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01B28197) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01B63A35) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01B67608) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01B78F73) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01B7C79E) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01B8DE7B) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01B91916) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01BA3121) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01BA6A99) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01BB8324) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01BBBBFE) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01BF7254) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01BFB08B) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01C0C739) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01C0C85C) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01C0C876) to Router$SV-AV-01
19.09.2017 13:36:48 1C14 I Sent message (id=01C10242) to Router$SV-AV-01

Anyway, attached (I hope) is a copy of the client message router logs showing the situation before and after the Sophos Message Router service restart.

Hope this helps.

Ruckus, many thanks for your input. I will review the material you suggested and will keep you posted of any developments.

Best regards,

John P

2 x SG450 (Version 9.714-4)

HA = Active-Passive

0 isoffice over 7 years ago in reply to isoffice

Hi all,

On a further note I have discovered when I run a netstat command on a PC that is shown as 'connected' in SEC, I get the following output:

C:\windows\system32>netstat -ano | findstr :8194
TCP    0.0.0.0:8194                 0.0.0.0:0             LISTENING         7644
TCP    10.63.26.110:8194       10.63.26.110:59106     ESTABLISHED     7644
TCP    10.63.26.110:59106     10.63.26.110:8194       ESTABLISHED     2348
TCP    10.63.26.110:60814     10.63.20.72:8194         ESTABLISHED     7644

C:\windows\system32>netstat -ano | findstr :8192
TCP    0.0.0.0:8192                  0.0.0.0:0                LISTENING       7644

Looks pretty OK. Client PC IP address is 10.63.26.110, SEC Server IP Address is 10.63.20.72. However, on a PC shown as 'disconnected' the following output is shown:

C:\windows\system32>netstat -ano | findstr :8194
TCP 0.0.0.0:8194                      0.0.0.0:0                       LISTENING 2496
TCP 127.0.0.1:8194                 127.0.0.1:49420            ESTABLISHED 2496
TCP 127.0.0.1:49420               127.0.0.1:8194              ESTABLISHED 2248

C:\windows\system32>netstat -ano | findstr :8192
TCP 0.0.0.0:8192                     0.0.0.0:0                        LISTENING 2496

Like Christian, I have no idea why the 'disconnected' client is resolving to a loopback address.

I'll pass these findings on to Sophos Support and let you know how things progress.

John P

2 x SG450 (Version 9.714-4)

HA = Active-Passive
Cancel
Vote Up 0 Vote Down

Cancel
0 WorEen over 7 years ago in reply to isoffice

Another day...

Early on Wednesday morning we supplied Sophos with SDU logs taken from both the server and an affected workstation. We were a little anxious at the time they were taking to respond and did so only after a prompt late yesterday afternoon. It transpires that Sophos are aware of this issue also affecting JohnP and commented that although information was limited in his case, after reviewing this thread suggested that the problem was likely the same. I would have thought they were identical to be honest.

Sophos suggested that our logs and those of JohnP indicated that the affected workstation were attempting to contact the console using TLS 1.0. I did not believe this was the case as we deploy from one of two images and as a result our workstations are to all intents and purposes identical. The suggestion also failed to address why only a relatively small percentage of these workstation are affected and that these were working last week. We installed Wireshark on the server and supplied Sophos with Wireshark logs after following the instruction in this article: https://community.sophos.com/kb/en-us/126422 Adding 8194 to the SSL box in HTTP and applying the filter ssl.handshake.version == 0x0301 && tcp.port == 8194 confirmed no computers were attempting to connect to the console using TLS 1.0

We are advised that the call has been passed to a level 2 engineer and a Sophos's senior engineer.

Ian.
Cancel
Vote Up 0 Vote Down

Cancel
0 jak over 7 years ago in reply to WorEen

Would you provide the logs of the router with loglevel 2 (trace logging enabled)?

It is detailed here: https://community.sophos.com/kb/en-us/30496 but essentially create a new DWORD value under:

HKEY_LOCAL_MACHINE\software\WOW6432Node\SOPHOS\messaging system\router

called LogLevel and set the value to 2.

If you restart the computer, next time it starts, the router will create a router log with level 2 logging.

I assume it still has the important error lines:
E Localhost address (e.g. 127/8) found in the IOR
E This router's IOR is invalid

if you leave it maybe a minute or 2, then I assume as before no change, then restart the router, in this case it works?

Each start of the router process will create a new log. Could you make available the last 2 logs, i.e. the failure at system startup and then success following the restart of the router.

Regards,

Jak
Cancel
Vote Up 0 Vote Down

Cancel

0 WorEen over 7 years ago in reply to jak

Hello Jak,

Following your instructions these logs were taken from a Latitude E7470 laptop with a clean install of Windows 10 and updated through Windows update. The laptop has been joined to our domain and the user account is a member of the local Administrators group. Winver reports the OS as Version 1607 |(OS Build 14391.1715). As you can see, the logs report that the routers IOR is invalid until the Sophos Message Router service is restarted upon which the routers IOR is successfully validated.

Log following reboot:

Extract
25.09.2017 08:56:49 0D88 T MessageRouter::validateIOR called
25.09.2017 08:56:49 0D88 T Endpoint found: 127.0.0.1:8193
25.09.2017 08:56:49 0D88 E Localhost address (e.g. 127/8) found in the IOR
25.09.2017 08:56:49 0D88 E This router's IOR is invalid
Full log below
_______________________________________________________________________________________________________________________

Fullscreen Full_log_below.txt Download

25.09.2017 08:56:48 0D88 I SOF: C:\ProgramData/Sophos/Remote Management System/3/Router/Logs/Router-20170925-075648.log
25.09.2017 08:56:48 0D88 I Sophos Messaging Router 4.1.1.127 starting...
25.09.2017 08:56:48 0D88 I Setting ACE_FD_SETSIZE to 138
25.09.2017 08:56:48 0D88 I Initializing CORBA...
25.09.2017 08:56:48 0D88 I Connection cache limit is 10
25.09.2017 08:56:49 0D88 D New context options = 1000004
25.09.2017 08:56:49 0D88 I Router::ConfigureSslContext: keeping legacy compatibility of TLS 1 and TLS 1.1.
25.09.2017 08:56:49 0D88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:56:49 0D88 T Added host network address:172.30.20.79:0
25.09.2017 08:56:49 0D88 T Added host network address:127.0.0.1:0
25.09.2017 08:56:49 0D88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:56:49 0D88 D Creating ORB...
25.09.2017 08:56:49 0D88 I Creating ORB runner with 4 threads
25.09.2017 08:56:49 0F60 D RunORB thread started
25.09.2017 08:56:49 0F24 D RunORB thread started
25.09.2017 08:56:49 0FBC D RunORB thread started
25.09.2017 08:56:49 0FB4 D RunORB thread started
25.09.2017 08:56:49 0D88 I Compliant certificate hashing algorithm.
25.09.2017 08:56:49 0D88 D Not requesting a new certificate.
25.09.2017 08:56:49 0D88 D Resolving the root object adapter...
25.09.2017 08:56:49 0D88 T >>> StatusReporting::StatusReporter::WriteReport
25.09.2017 08:56:49 0D88 I This computer is part of the domain PJL
25.09.2017 08:56:49 0D88 T >>> StatusReporting::StatusReporter::WriteAsXML
25.09.2017 08:56:49 0D88 T >>> StatusReporting::DNSSection::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::DNSSection::WriteAsXML
25.09.2017 08:56:49 0D88 T >>> StatusReporting::CertificationSection::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::CertificationSection::WriteAsXML
25.09.2017 08:56:49 0D88 T >>> StatusReporting::IncomingSection::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::IncomingSection::WriteAsXML
25.09.2017 08:56:49 0D88 T >>> StatusReporting::OutgoingSection::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::OutgoingSection::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::StatusReporter::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::StatusReporter::WriteReport
25.09.2017 08:56:49 0D88 D Creating object adapters...
25.09.2017 08:56:49 0D88 D Creating MessageRouter CORBA object...
25.09.2017 08:56:49 0D88 I This router's IOR:
IOR:010000002600000049444c3a536f70686f734d6573736167696e672f4d657373616765526f757465723a312e300000000100000000000000a0000000010102000a0000003132372e302e302e310001204100000014010f004e5550000000210000000001000000526f6f74504f4100526f7574657250657273697374656e740003000000010000004d657373616765526f757465720000000300000000000000080000000100e001004f415401000000180000000100e001010001000100000001000105090101000000000014000000080000000100a60086000220
25.09.2017 08:56:49 0D88 T MessageRouter::validateIOR called
25.09.2017 08:56:49 0D88 T Endpoint found: 127.0.0.1:8193
25.09.2017 08:56:49 0D88 E Localhost address (e.g. 127/8) found in the IOR
25.09.2017 08:56:49 0D88 E This router's IOR is invalid
25.09.2017 08:56:49 0D88 T >>> StatusReporting::StatusReporter::Done
25.09.2017 08:56:49 0D88 T DNS            : problem 0, changed 0, already reported 0
25.09.2017 08:56:49 0D88 T Certification  : problem 0, changed 0, already reported 0
25.09.2017 08:56:49 0D88 T Incoming       : problem 0, changed 0, already reported 0
25.09.2017 08:56:49 0D88 T Outgoing       : problem 1, changed 1, already reported 0
25.09.2017 08:56:49 0D88 T >>> StatusReporting::OutgoingSection::LogNow
25.09.2017 08:56:49 0D88 T >>> void __thiscall System::EventLogger::LogEvent(unsigned long,unsigned short,const char *,const char *,const char *,const char *,const char *,const char *,const char *,const char *,const char *) const
25.09.2017 08:56:49 0D88 T >>> void __thiscall System::EventLogger::LogEvent(unsigned long,unsigned short,unsigned short,const char *[]) const
25.09.2017 08:56:49 0D88 T <<< void __thiscall System::EventLogger::LogEvent(unsigned long,unsigned short,unsigned short,const char *[]) const
25.09.2017 08:56:49 0D88 T <<< void __thiscall System::EventLogger::LogEvent(unsigned long,unsigned short,const char *,const char *,const char *,const char *,const char *,const char *,const char *,const char *,const char *) const
25.09.2017 08:56:49 0D88 T <<< StatusReporting::OutgoingSection::LogNow
25.09.2017 08:56:49 0D88 D class StatusReporting::OutgoingSection changed
25.09.2017 08:56:49 0D88 T >>> StatusReporting::StatusReporter::WriteReport
25.09.2017 08:56:49 0D88 I This computer is part of the domain PJL
25.09.2017 08:56:49 0D88 T >>> StatusReporting::StatusReporter::WriteAsXML
25.09.2017 08:56:49 0D88 T >>> StatusReporting::DNSSection::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::DNSSection::WriteAsXML
25.09.2017 08:56:49 0D88 T >>> StatusReporting::CertificationSection::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::CertificationSection::WriteAsXML
25.09.2017 08:56:49 0D88 T >>> StatusReporting::IncomingSection::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::IncomingSection::WriteAsXML
25.09.2017 08:56:49 0D88 T >>> StatusReporting::OutgoingSection::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::OutgoingSection::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::StatusReporter::WriteAsXML
25.09.2017 08:56:49 0D88 T <<< StatusReporting::StatusReporter::WriteReport
25.09.2017 08:56:49 0D88 T <<< StatusReporting::StatusReporter::Done
25.09.2017 08:56:49 0D88 D Setting NotificationThresholdInitialRetrySecs to 3600
25.09.2017 08:56:49 0D88 D Setting NotificationThresholdMaxRetrySecs to 172800
25.09.2017 08:56:49 0D88 I Reading router table file
25.09.2017 08:56:49 0D88 D Loading envelopes from persistent storage...
25.09.2017 08:56:49 0D88 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000004.msg" for [id=01C54536, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent]
25.09.2017 08:56:49 0D88 T Envelope::Shrink
25.09.2017 08:56:49 0D88 D Shrunk Envelope, id=01C54536
25.09.2017 08:56:49 0D88 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/0000000b.msg" for [id=01C7E837, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent]
25.09.2017 08:56:49 0D88 T Envelope::Shrink
25.09.2017 08:56:49 0D88 D Shrunk Envelope, id=01C7E837
25.09.2017 08:56:49 0D88 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/0000000c.msg" for [id=01C8416C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 08:56:49 0D88 T Envelope::Shrink
25.09.2017 08:56:49 0D88 D Shrunk Envelope, id=01C8416C
25.09.2017 08:56:49 0D88 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/0000000d.msg" for [id=01C8830C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 08:56:49 0D88 T Envelope::Shrink
25.09.2017 08:56:49 0D88 D Shrunk Envelope, id=01C8830C
25.09.2017 08:56:49 0D88 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000011.msg" for [id=01C8B165, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 08:56:49 0D88 T Envelope::Shrink
25.09.2017 08:56:49 0D88 D Shrunk Envelope, id=01C8B165
25.09.2017 08:56:49 0D88 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000012.msg" for [id=01C8B27C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent]
25.09.2017 08:56:49 0D88 T Envelope::Shrink
25.09.2017 08:56:49 0D88 D Shrunk Envelope, id=01C8B27C
25.09.2017 08:56:49 0D88 D Activating CORBA objects...
25.09.2017 08:56:49 0D88 I Host name: scopat-win10
25.09.2017 08:56:49 0D88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:56:49 0D88 T Added host network address:172.30.20.79:0
25.09.2017 08:56:49 0D88 T Added host network address:127.0.0.1:0
25.09.2017 08:56:49 0D88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:56:49 0D88 I Local IP addresses: 172.30.20.79 
25.09.2017 08:56:49 0D88 I Resolved name: scopat-win10.pjl.local
25.09.2017 08:56:49 0D88 I Resolved alias/es: 
25.09.2017 08:56:49 0D88 I Resolved IP addresses: 127.0.0.1 
25.09.2017 08:56:49 0D88 I Resolved reverse names/aliases: scopat-win10.pjl.local 
25.09.2017 08:56:49 0D88 T Router::doStartRouting() called
25.09.2017 08:56:49 0D88 T Total time for retrying ACE socket connection 300
25.09.2017 08:56:49 0D88 T Number of retries when retrying ACE socket connection 100
25.09.2017 08:56:49 0D88 T Pause between retries when retrying ACE socket connection 2000
25.09.2017 08:56:49 0D88 T Pause variation percentage range 0
25.09.2017 08:56:49 0D88 D Router will not restart when it detects an EM or parent sender thread has failed to send 5000 messages.
25.09.2017 08:56:49 0074 T +++ class MessageRouter::SenderWorker derived from BasicThreadHelper: starting.
25.09.2017 08:56:49 0D88 D Initialising router with 0 notification threshold worker threads
25.09.2017 08:56:49 0EC8 T +++ class MessageRouter::SenderWorker derived from BasicThreadHelper: starting.
25.09.2017 08:56:49 0D38 T +++ class MessageRouter::SenderWorker derived from BasicThreadHelper: starting.
25.09.2017 08:56:49 1004 T +++ class MessageRouter::RouterThread derived from BasicThreadHelper: starting.
25.09.2017 08:56:49 0D88 I Waiting for messages...
25.09.2017 08:56:49 1004 I Routing to parent: id=01C54536, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent
25.09.2017 08:56:49 0D88 D Reducing Size
25.09.2017 08:56:49 1004 I Routing to parent: id=01C7E837, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent
25.09.2017 08:56:49 0D88 D RouterSystemCheck: percentageThreshold 85, minimumPortNumToCount 1024, checkIntervalSecs 3600, reportIntervalSecs 86400
25.09.2017 08:56:49 1004 I Routing to parent: id=01C8416C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply
25.09.2017 08:56:49 1004 I Routing to parent: id=01C8830C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply
25.09.2017 08:56:49 0D88 T RouterSystemCheck::getMaxUserPort()
25.09.2017 08:56:49 1004 I Routing to parent: id=01C8B165, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply
25.09.2017 08:56:49 0D88 D RouterSystemCheck::getMaxUserPort(), no MaxUserPort value in Registry
25.09.2017 08:56:49 0D88 D RouterSystemCheck::getMaxUserPort(), value (0) is too low, assuming 16384
25.09.2017 08:56:49 0D88 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 4, max number of user ports 15360
25.09.2017 08:56:49 0D88 T CertificateRegenerationChecker::IsItTimeToRefreshCertificate(): key size and hashing algorithm are valid.
25.09.2017 08:56:49 1004 I Routing to parent: id=01C8B27C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent
25.09.2017 08:56:49 100C T +++ class MessageRouter::TimeoutThread derived from BasicThreadHelper: starting.
25.09.2017 08:56:49 1014 T +++ class MessageRouter::HostIPAddressMonitor<class ACEHelpers::IPAddressSet> derived from BasicThreadHelper: starting.
25.09.2017 08:56:49 1014 T HostIPAddressMonitor::Process started
25.09.2017 08:56:49 100C T TimeoutThread::Process() checking table
25.09.2017 08:56:49 1010 T +++ class MessageRouter::IOR_Sender derived from BasicThreadHelper: starting.
25.09.2017 08:56:49 100C D TimeoutThread::CheckEntry() adding entry: 
25.09.2017 08:56:49 1008 T +++ class MessageRouter::GetterThread derived from BasicThreadHelper: starting.
25.09.2017 08:56:49 1008 T GetterThread::Process() checking table
25.09.2017 08:56:49 1018 T +++ class MessageRouter::TimeoutWorker derived from BasicThreadHelper: starting.
25.09.2017 08:56:49 101C T +++ class MessageRouter::GetterWorker derived from BasicThreadHelper: starting.
25.09.2017 08:56:49 1020 T +++ class MessageRouter::GetterWorker derived from BasicThreadHelper: starting.
25.09.2017 08:56:51 0FB4 T MessageRouter::GetClient() called
25.09.2017 08:56:51 0F60 T Client::Register() called
25.09.2017 08:56:51 0FB4 T Client::LogonPushPush() called
25.09.2017 08:56:51 0FB4 I Client::LogonPushPush() successfully called back to client
25.09.2017 08:56:51 0FB4 D Created "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000013.msg" for [id=03C8B6C3, origin=Router$scopat-win10:441054, dest=Router$scopat-win10:441054.Agent, type=EM-ClientLogon]
25.09.2017 08:56:51 0FB4 T Envelope::Shrink
25.09.2017 08:56:51 0FB4 D Shrunk Envelope, id=03C8B6C3
25.09.2017 08:56:51 0FB4 I Logged on Agent as a client
25.09.2017 08:56:51 1004 I Routing to Agent: id=03C8B6C3, origin=Router$scopat-win10:441054, dest=Router$scopat-win10:441054.Agent, type=EM-ClientLogon
25.09.2017 08:56:51 0EC8 T Envelope::GetOriginatorCert
25.09.2017 08:56:51 0EC8 T Envelope::Expand
25.09.2017 08:56:51 0FBC T ClientMessageConsumer::Heartbeat() called
25.09.2017 08:56:51 0EC8 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000013.msg" for [id=03C8B6C3, origin=Router$scopat-win10:441054, dest=Router$scopat-win10:441054.Agent, type=EM-ClientLogon]
25.09.2017 08:56:51 0EC8 T Envelope::GetData
25.09.2017 08:56:51 0EC8 T Envelope::Expand
25.09.2017 08:56:51 0EC8 T Envelope::GetOriginatorCert
25.09.2017 08:56:51 0EC8 T Envelope::Expand
25.09.2017 08:56:51 0EC8 D Expanded Envelope, id=03C8B6C3
25.09.2017 08:56:51 0EC8 T Envelope::GetData
25.09.2017 08:56:51 0EC8 T Envelope::Expand
25.09.2017 08:56:51 0EC8 T Sending message (id=03C8B6C3) to Agent
25.09.2017 08:56:51 0EC8 I Sent message (id=03C8B6C3) to Agent
25.09.2017 08:56:51 0FBC T ClientMessageConsumer::SendMessage() called
25.09.2017 08:56:51 0FBC D Created "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000014.msg" for [id=05C8B6C3, origin=Router$scopat-win10:441054.Agent, dest=:, type=EM-NotifyClientUpdates]
25.09.2017 08:56:51 0FBC T Envelope::Shrink
25.09.2017 08:56:51 0FBC D Shrunk Envelope, id=05C8B6C3
25.09.2017 08:56:51 1004 I Received message for this router
25.09.2017 08:56:51 1004 I EM-NotifyClientUpdates originator Router$scopat-win10:441054.Agent
25.09.2017 08:56:51 1004 D Created "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000015.msg" for [id=07C8B6C3, origin=Router$scopat-win10:441054, dest=Router$scopat-win10:441054.Agent, type=EM-NotifyClientUpdates-Reply]
25.09.2017 08:56:51 1004 T Envelope::Shrink
25.09.2017 08:56:51 1004 D Shrunk Envelope, id=07C8B6C3
25.09.2017 08:56:51 1004 I Routing to Agent: id=07C8B6C3, origin=Router$scopat-win10:441054, dest=Router$scopat-win10:441054.Agent, type=EM-NotifyClientUpdates-Reply
25.09.2017 08:56:51 0D38 T Envelope::GetOriginatorCert
25.09.2017 08:56:51 0D38 T Envelope::Expand
25.09.2017 08:56:51 0D38 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000015.msg" for [id=07C8B6C3, origin=Router$scopat-win10:441054, dest=Router$scopat-win10:441054.Agent, type=EM-NotifyClientUpdates-Reply]
25.09.2017 08:56:51 0D38 T Envelope::GetData
25.09.2017 08:56:51 0D38 T Envelope::Expand
25.09.2017 08:56:51 0D38 T Envelope::GetOriginatorCert
25.09.2017 08:56:51 0D38 T Envelope::Expand
25.09.2017 08:56:51 0D38 D Expanded Envelope, id=07C8B6C3
25.09.2017 08:56:51 0D38 T Envelope::GetData
25.09.2017 08:56:51 0D38 T Envelope::Expand
25.09.2017 08:56:51 0D38 T Sending message (id=07C8B6C3) to Agent
25.09.2017 08:56:51 0D38 I Sent message (id=07C8B6C3) to Agent
25.09.2017 08:56:54 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:56:54 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:56:54 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:56:54 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:56:59 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:56:59 1008 T GetterThread::Process() checking table
25.09.2017 08:56:59 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:56:59 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:56:59 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:04 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:04 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:04 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:04 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:09 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:09 1008 T GetterThread::Process() checking table
25.09.2017 08:57:09 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:09 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:09 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:11 0FBC T ClientMessageConsumer::SendMessage() called
25.09.2017 08:57:11 0FBC D Created "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000016.msg" for [id=01C8B6D7, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 08:57:11 0FBC T Envelope::Shrink
25.09.2017 08:57:11 0FBC D Shrunk Envelope, id=01C8B6D7
25.09.2017 08:57:11 1004 I Routing to parent: id=01C8B6D7, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply
25.09.2017 08:57:14 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:14 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:14 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:14 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:19 1008 T GetterThread::Process() checking table
25.09.2017 08:57:19 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:19 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:19 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:19 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:24 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:24 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:24 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:24 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:29 1008 T GetterThread::Process() checking table
25.09.2017 08:57:29 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:29 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:29 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:29 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:34 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:34 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:34 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:34 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:39 1008 T GetterThread::Process() checking table
25.09.2017 08:57:39 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:39 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:39 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:39 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:44 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:44 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:44 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:44 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:49 1008 T GetterThread::Process() checking table
25.09.2017 08:57:49 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:49 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:49 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:49 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:54 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:54 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:54 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:54 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:57:59 100C T TimeoutThread::Process() checking table
25.09.2017 08:57:59 100C D TimeoutThread::CheckEntry() adding entry: 
25.09.2017 08:57:59 1008 T GetterThread::Process() checking table
25.09.2017 08:57:59 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:57:59 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:57:59 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:57:59 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:04 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:04 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:04 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:04 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:09 1008 T GetterThread::Process() checking table
25.09.2017 08:58:09 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:09 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:09 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:09 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:14 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:14 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:14 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:14 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:19 1008 T GetterThread::Process() checking table
25.09.2017 08:58:19 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:19 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:19 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:19 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:24 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:24 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:24 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:24 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:29 1008 T GetterThread::Process() checking table
25.09.2017 08:58:29 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:29 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:29 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:29 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:34 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:34 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:34 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:34 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:39 1008 T GetterThread::Process() checking table
25.09.2017 08:58:39 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:39 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:39 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:39 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:44 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:44 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:44 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:44 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:49 1008 T GetterThread::Process() checking table
25.09.2017 08:58:49 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:49 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:49 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:49 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:54 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:54 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:54 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:54 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:58:59 1008 T GetterThread::Process() checking table
25.09.2017 08:58:59 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:58:59 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:58:59 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:58:59 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:59:04 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:59:04 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:59:04 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:59:04 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:59:09 100C T TimeoutThread::Process() checking table
25.09.2017 08:59:09 100C D TimeoutThread::CheckEntry() adding entry: 
25.09.2017 08:59:09 1008 T GetterThread::Process() checking table
25.09.2017 08:59:09 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:59:09 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:59:09 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:59:09 1014 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 08:59:14 1014 T IPAddressSet::InitialiseWithHost() called
25.09.2017 08:59:14 1014 T Added host network address:172.30.20.79:0
25.09.2017 08:59:14 1014 T Added host network address:127.0.0.1:0
25.09.2017 08:59:14 1014 T IPAddressSet::InitialiseWithHost() returns
_______________________________________________________________________________________________________________________
Log after restarting Sophos Message Router service

Extract
25.09.2017 09:00:24 0984 T MessageRouter::validateIOR called
25.09.2017 09:00:24 0984 T Endpoint found: 172.30.20.79:8193
25.09.2017 09:00:24 0984 I Successfully validated this router's IOR
Full log below
_______________________________________________________________________________________________________________________
25.09.2017 09:00:23 0984 I SOF: C:\ProgramData/Sophos/Remote Management System/3/Router/Logs/Router-20170925-080023.log
25.09.2017 09:00:23 0984 I Sophos Messaging Router 4.1.1.127 starting...
25.09.2017 09:00:23 0984 I Setting ACE_FD_SETSIZE to 138
25.09.2017 09:00:23 0984 I Initializing CORBA...
25.09.2017 09:00:23 0984 I Connection cache limit is 10
25.09.2017 09:00:23 0984 D New context options = 1000004
25.09.2017 09:00:23 0984 I Router::ConfigureSslContext: keeping legacy compatibility of TLS 1 and TLS 1.1.
25.09.2017 09:00:23 0984 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:00:23 0984 T Added host network address:172.30.20.79:0
25.09.2017 09:00:23 0984 T Added host network address:127.0.0.1:0
25.09.2017 09:00:23 0984 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:00:23 0984 D Creating ORB...
25.09.2017 09:00:23 0984 I Creating ORB runner with 4 threads
25.09.2017 09:00:23 0AA4 D RunORB thread started
25.09.2017 09:00:23 1664 D RunORB thread started
25.09.2017 09:00:23 0F08 D RunORB thread started
25.09.2017 09:00:23 0F48 D RunORB thread started
25.09.2017 09:00:24 0984 I Compliant certificate hashing algorithm.
25.09.2017 09:00:24 0984 D Not requesting a new certificate.
25.09.2017 09:00:24 0984 D Resolving the root object adapter...
25.09.2017 09:00:24 0984 T >>> StatusReporting::StatusReporter::WriteReport
25.09.2017 09:00:24 0984 I This computer is part of the domain PJL
25.09.2017 09:00:24 0984 T >>> StatusReporting::StatusReporter::WriteAsXML
25.09.2017 09:00:24 0984 T >>> StatusReporting::DNSSection::WriteAsXML
25.09.2017 09:00:24 0984 T <<< StatusReporting::DNSSection::WriteAsXML
25.09.2017 09:00:24 0984 T >>> StatusReporting::CertificationSection::WriteAsXML
25.09.2017 09:00:24 0984 T <<< StatusReporting::CertificationSection::WriteAsXML
25.09.2017 09:00:24 0984 T >>> StatusReporting::IncomingSection::WriteAsXML
25.09.2017 09:00:24 0984 T <<< StatusReporting::IncomingSection::WriteAsXML
25.09.2017 09:00:24 0984 T >>> StatusReporting::OutgoingSection::WriteAsXML
25.09.2017 09:00:24 0984 T <<< StatusReporting::OutgoingSection::WriteAsXML
25.09.2017 09:00:24 0984 T <<< StatusReporting::StatusReporter::WriteAsXML
25.09.2017 09:00:24 0984 T <<< StatusReporting::StatusReporter::WriteReport
25.09.2017 09:00:24 0984 D Creating object adapters...
25.09.2017 09:00:24 0984 D Creating MessageRouter CORBA object...
25.09.2017 09:00:24 0984 I This router's IOR:
IOR:010000002600000049444c3a536f70686f734d6573736167696e672f4d657373616765526f757465723a312e300000000100000000000000a4000000010102000d0000003137322e33302e32302e3739000001204100000014010f004e5550000000210000000001000000526f6f74504f4100526f7574657250657273697374656e740003000000010000004d657373616765526f757465720000000300000000000000080000000100dd01004f415401000000180000000100dd01010001000100000001000105090101000000000014000000080000000100a60086000220
25.09.2017 09:00:24 0984 T MessageRouter::validateIOR called
25.09.2017 09:00:24 0984 T Endpoint found: 172.30.20.79:8193
25.09.2017 09:00:24 0984 I Successfully validated this router's IOR
25.09.2017 09:00:24 0984 T >>> StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 0984 T DNS            : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 0984 T Certification  : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 0984 T Incoming       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 0984 T Outgoing       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 0984 T <<< StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 0984 D Setting NotificationThresholdInitialRetrySecs to 3600
25.09.2017 09:00:24 0984 D Setting NotificationThresholdMaxRetrySecs to 172800
25.09.2017 09:00:24 0984 I Reading router table file
25.09.2017 09:00:24 0984 D Loading envelopes from persistent storage...
25.09.2017 09:00:24 0984 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000004.msg" for [id=01C54536, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent]
25.09.2017 09:00:24 0984 T Envelope::Shrink
25.09.2017 09:00:24 0984 D Shrunk Envelope, id=01C54536
25.09.2017 09:00:24 0984 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/0000000b.msg" for [id=01C7E837, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent]
25.09.2017 09:00:24 0984 T Envelope::Shrink
25.09.2017 09:00:24 0984 D Shrunk Envelope, id=01C7E837
25.09.2017 09:00:24 0984 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/0000000c.msg" for [id=01C8416C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 09:00:24 0984 T Envelope::Shrink
25.09.2017 09:00:24 0984 D Shrunk Envelope, id=01C8416C
25.09.2017 09:00:24 0984 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/0000000d.msg" for [id=01C8830C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 09:00:24 0984 T Envelope::Shrink
25.09.2017 09:00:24 0984 D Shrunk Envelope, id=01C8830C
25.09.2017 09:00:24 0984 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000011.msg" for [id=01C8B165, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 09:00:24 0984 T Envelope::Shrink
25.09.2017 09:00:24 0984 D Shrunk Envelope, id=01C8B165
25.09.2017 09:00:24 0984 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000012.msg" for [id=01C8B27C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent]
25.09.2017 09:00:24 0984 T Envelope::Shrink
25.09.2017 09:00:24 0984 D Shrunk Envelope, id=01C8B27C
25.09.2017 09:00:24 0984 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000016.msg" for [id=01C8B6D7, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 09:00:24 0984 T Envelope::Shrink
25.09.2017 09:00:24 0984 D Shrunk Envelope, id=01C8B6D7
25.09.2017 09:00:24 0984 D Activating CORBA objects...
25.09.2017 09:00:24 0984 I Host name: scopat-win10
25.09.2017 09:00:24 0984 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:00:24 0984 T Added host network address:172.30.20.79:0
25.09.2017 09:00:24 0984 T Added host network address:127.0.0.1:0
25.09.2017 09:00:24 0984 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:00:24 0984 I Local IP addresses: 172.30.20.79 
25.09.2017 09:00:24 0984 I Resolved name: scopat-win10.pjl.local
25.09.2017 09:00:24 0984 I Resolved alias/es: 
25.09.2017 09:00:24 0984 I Resolved IP addresses: 172.30.20.79 
25.09.2017 09:00:24 0984 I Resolved reverse names/aliases: scopat-win10.pjl.local 
25.09.2017 09:00:24 0984 T Router::doStartRouting() called
25.09.2017 09:00:24 0984 T Total time for retrying ACE socket connection 300
25.09.2017 09:00:24 0984 T Number of retries when retrying ACE socket connection 100
25.09.2017 09:00:24 0984 T Pause between retries when retrying ACE socket connection 2000
25.09.2017 09:00:24 0984 T Pause variation percentage range 0
25.09.2017 09:00:24 0984 D Router will not restart when it detects an EM or parent sender thread has failed to send 5000 messages.
25.09.2017 09:00:24 19B0 T +++ class MessageRouter::SenderWorker derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 1940 T +++ class MessageRouter::SenderWorker derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 0404 T +++ class MessageRouter::SenderWorker derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 0984 D Initialising router with 0 notification threshold worker threads
25.09.2017 09:00:24 1710 T +++ class MessageRouter::RouterThread derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 0984 I Waiting for messages...
25.09.2017 09:00:24 1710 I Routing to parent: id=01C54536, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent
25.09.2017 09:00:24 18C0 T +++ class MessageRouter::GetterThread derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 0984 D Reducing Size
25.09.2017 09:00:24 1B80 T +++ class MessageRouter::TimeoutThread derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 18C0 T GetterThread::Process() checking table
25.09.2017 09:00:24 1B80 T TimeoutThread::Process() checking table
25.09.2017 09:00:24 1710 I Routing to parent: id=01C7E837, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent
25.09.2017 09:00:24 1B80 D TimeoutThread::CheckEntry() adding entry: 
25.09.2017 09:00:24 1710 I Routing to parent: id=01C8416C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply
25.09.2017 09:00:24 0984 D RouterSystemCheck: percentageThreshold 85, minimumPortNumToCount 1024, checkIntervalSecs 3600, reportIntervalSecs 86400
25.09.2017 09:00:24 1348 T +++ class MessageRouter::IOR_Sender derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 1A98 T +++ class MessageRouter::ParentLogon derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 1710 I Routing to parent: id=01C8830C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply
25.09.2017 09:00:24 1A98 I Getting parent router IOR from 172.30.1.46:8192
25.09.2017 09:00:24 1A98 T >>> StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 1A98 T DNS            : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Certification  : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1710 I Routing to parent: id=01C8B165, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply
25.09.2017 09:00:24 1A98 T Incoming       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Outgoing       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T <<< StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 0984 T RouterSystemCheck::getMaxUserPort()
25.09.2017 09:00:24 1710 I Routing to parent: id=01C8B27C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent
25.09.2017 09:00:24 1710 I Routing to parent: id=01C8B6D7, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply
25.09.2017 09:00:24 1B88 T +++ class MessageRouter::HostIPAddressMonitor<class ACEHelpers::IPAddressSet> derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 0984 D RouterSystemCheck::getMaxUserPort(), no MaxUserPort value in Registry
25.09.2017 09:00:24 1B88 T HostIPAddressMonitor::Process started
25.09.2017 09:00:24 0984 D RouterSystemCheck::getMaxUserPort(), value (0) is too low, assuming 16384
25.09.2017 09:00:24 1B64 T +++ class MessageRouter::GetterWorker derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 0984 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
25.09.2017 09:00:24 0984 T CertificateRegenerationChecker::IsItTimeToRefreshCertificate(): key size and hashing algorithm are valid.
25.09.2017 09:00:24 0948 T +++ class MessageRouter::GetterWorker derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 07DC T +++ class MessageRouter::TimeoutWorker derived from BasicThreadHelper: starting.
25.09.2017 09:00:24 1A98 T >>> StatusReporting::StatusReporter::SetActualParent
25.09.2017 09:00:24 1A98 D Actual parent is `172.30.1.46`
25.09.2017 09:00:24 1A98 T <<< StatusReporting::StatusReporter::SetActualParent
25.09.2017 09:00:24 1A98 T >>> StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 1A98 T DNS            : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Certification  : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Incoming       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Outgoing       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T <<< StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 1A98 T >>> StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 1A98 T DNS            : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Certification  : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Incoming       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Outgoing       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T <<< StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 1A98 I Received parent router's IOR:
IOR:010000002600000049444c3a536f70686f734d6573736167696e672f4d657373616765526f757465723a312e300000000100000000000000a4000000010102000c0000003137322e33302e312e343600012000004100000014010f004e5550000000210000000001000000526f6f74504f4100526f7574657250657273697374656e740003000000010000004d657373616765526f757465720000000300000000000000080000000100a800004f415401000000180000000100a800010001000100000001000105090101000000000014000000080000000100a60086000220
25.09.2017 09:00:24 1A98 T MessageRouter::validateIOR called
25.09.2017 09:00:24 1A98 T Endpoint found: 172.30.1.46:8193
25.09.2017 09:00:24 1A98 T >>> StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 1A98 T DNS            : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Certification  : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Incoming       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T Outgoing       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T <<< StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 1A98 I Successfully validated parent router's IOR
25.09.2017 09:00:24 1A98 I Accessing parent
25.09.2017 09:00:24 1A98 I SSL handshake done, local IP address = 172.30.20.79
25.09.2017 09:00:24 1A98 I Parent is Router$pris
25.09.2017 09:00:24 1A98 D Already registered with parent router
25.09.2017 09:00:24 1A98 T RouterTableEntry::LogonToParentRouter
25.09.2017 09:00:24 1A98 I RouterTableEntry::LogonToParentRouter() - logging on as active consumer
25.09.2017 09:00:24 1A98 D RouterTableEntry::unsafe_enablePolling(): set polling interval to 681 seconds for Router$pris
25.09.2017 09:00:24 1A98 I RouterTableEntry state (router, logging on): Router$pris is passive consumer, passive supplier
25.09.2017 09:00:24 1A98 D RouterTableEntry::readyForNotifiedPoll(): await poll of Router$pris
25.09.2017 09:00:24 1A98 I Logged on to parent router as Router$scopat-win10:441054
25.09.2017 09:00:24 1A98 T >>> StatusReporting::StatusReporter::WriteReport
25.09.2017 09:00:24 1B64 D GetterWorker::ProcessEntry() - polling Router$pris
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1A98 I This computer is part of the domain PJL
25.09.2017 09:00:24 1940 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000004.msg" for [id=01C54536, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent]
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Expanded Envelope, id=01C54536
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Sending message (id=01C54536) to Router$pris
25.09.2017 09:00:24 1B64 D RouterTableEntry::successfulGet(): re-started polling interval for Router$pris
25.09.2017 09:00:24 1A98 T >>> StatusReporting::StatusReporter::WriteAsXML
25.09.2017 09:00:24 1B64 D ~~~ IncomingSection: 0 strikes.
25.09.2017 09:00:24 1B64 T >>> StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 1B64 T DNS            : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T >>> StatusReporting::DNSSection::WriteAsXML
25.09.2017 09:00:24 1B64 T Certification  : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T <<< StatusReporting::DNSSection::WriteAsXML
25.09.2017 09:00:24 1B64 T Incoming       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T >>> StatusReporting::CertificationSection::WriteAsXML
25.09.2017 09:00:24 1B64 T Outgoing       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 1A98 T <<< StatusReporting::CertificationSection::WriteAsXML
25.09.2017 09:00:24 1B64 T <<< StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 1A98 T >>> StatusReporting::IncomingSection::WriteAsXML
25.09.2017 09:00:24 1A98 T <<< StatusReporting::IncomingSection::WriteAsXML
25.09.2017 09:00:24 1A98 T >>> StatusReporting::OutgoingSection::WriteAsXML
25.09.2017 09:00:24 1A98 T <<< StatusReporting::OutgoingSection::WriteAsXML
25.09.2017 09:00:24 1A98 T <<< StatusReporting::StatusReporter::WriteAsXML
25.09.2017 09:00:24 1A98 T <<< StatusReporting::StatusReporter::WriteReport
25.09.2017 09:00:24 1940 I Sent message (id=01C54536) to Router$pris
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/0000000b.msg" for [id=01C7E837, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent]
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Expanded Envelope, id=01C7E837
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Sending message (id=01C7E837) to Router$pris
25.09.2017 09:00:24 1940 I Sent message (id=01C7E837) to Router$pris
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/0000000c.msg" for [id=01C8416C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Expanded Envelope, id=01C8416C
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Sending message (id=01C8416C) to Router$pris
25.09.2017 09:00:24 1940 I Sent message (id=01C8416C) to Router$pris
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/0000000d.msg" for [id=01C8830C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Expanded Envelope, id=01C8830C
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Sending message (id=01C8830C) to Router$pris
25.09.2017 09:00:24 1940 I Sent message (id=01C8830C) to Router$pris
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000011.msg" for [id=01C8B165, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Expanded Envelope, id=01C8B165
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Sending message (id=01C8B165) to Router$pris
25.09.2017 09:00:24 1940 I Sent message (id=01C8B165) to Router$pris
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000012.msg" for [id=01C8B27C, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-EntityEvent]
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Expanded Envelope, id=01C8B27C
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Sending message (id=01C8B27C) to Router$pris
25.09.2017 09:00:24 1940 I Sent message (id=01C8B27C) to Router$pris
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Loaded "C:\ProgramData/Sophos/Remote Management System/3/Router/Envelopes/00000016.msg" for [id=01C8B6D7, origin=Router$scopat-win10:441054.Agent, dest=EM, type=EM-GetStatus-Reply]
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Envelope::GetOriginatorCert
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 D Expanded Envelope, id=01C8B6D7
25.09.2017 09:00:24 1940 T Envelope::GetData
25.09.2017 09:00:24 1940 T Envelope::Expand
25.09.2017 09:00:24 1940 T Sending message (id=01C8B6D7) to Router$pris
25.09.2017 09:00:24 1940 I Sent message (id=01C8B6D7) to Router$pris
25.09.2017 09:00:24 0F48 I SSL handshake done, local IP address = 172.30.20.79
25.09.2017 09:00:24 0F08 T NotifyConsumer::NotificationThreshold() called
25.09.2017 09:00:24 0F08 T >>> StatusReporting::IncomingSection::ThresholdCall
25.09.2017 09:00:24 0F08 D ~~~ IncomingSection: 0 strikes.
25.09.2017 09:00:24 0F08 T <<< StatusReporting::IncomingSection::ThresholdCall
25.09.2017 09:00:24 0F08 T >>> StatusReporting::StatusReporter::Done
25.09.2017 09:00:24 0F08 T DNS            : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 0F08 T Certification  : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 0F08 T Incoming       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 0F08 T Outgoing       : problem 0, changed 0, already reported 0
25.09.2017 09:00:24 0F08 T <<< StatusReporting::StatusReporter::Done
25.09.2017 09:00:29 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:00:29 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:00:29 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:00:29 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:00:34 18C0 T GetterThread::Process() checking table
25.09.2017 09:00:34 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:00:34 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:00:34 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:00:34 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:00:39 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:00:39 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:00:39 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:00:39 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:00:44 18C0 T GetterThread::Process() checking table
25.09.2017 09:00:44 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:00:44 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:00:44 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:00:44 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:00:49 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:00:49 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:00:49 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:00:49 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:00:54 18C0 T GetterThread::Process() checking table
25.09.2017 09:00:54 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:00:54 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:00:54 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:00:54 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:00:59 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:00:59 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:00:59 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:00:59 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:01:04 18C0 T GetterThread::Process() checking table
25.09.2017 09:01:04 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:01:04 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:01:04 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:01:04 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:01:09 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:01:09 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:01:09 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:01:09 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:01:14 18C0 T GetterThread::Process() checking table
25.09.2017 09:01:14 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:01:14 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:01:14 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:01:14 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:01:19 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:01:19 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:01:19 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:01:19 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:01:24 18C0 T GetterThread::Process() checking table
25.09.2017 09:01:24 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:01:24 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:01:24 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:01:24 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:01:29 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:01:29 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:01:29 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:01:29 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:01:34 1B80 T TimeoutThread::Process() checking table
25.09.2017 09:01:34 18C0 T GetterThread::Process() checking table
25.09.2017 09:01:34 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:01:34 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:01:34 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:01:34 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:01:39 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:01:39 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:01:39 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:01:39 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:01:44 18C0 T GetterThread::Process() checking table
25.09.2017 09:01:44 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:01:44 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:01:44 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:01:44 1B88 T IPAddressSet::InitialiseWithHost() returns
25.09.2017 09:01:49 1B88 T IPAddressSet::InitialiseWithHost() called
25.09.2017 09:01:49 1B88 T Added host network address:172.30.20.79:0
25.09.2017 09:01:49 1B88 T Added host network address:127.0.0.1:0
25.09.2017 09:01:49 1B88 T IPAddressSet::InitialiseWithHost() returns

_______________________________________________________________________________________________________________________

Ian.

0 ruckus over 7 years ago in reply to WorEen

FYI: WorEen I edited your reply and attached the full log as a file to make reading it easier. Hope it helps.

- - - - - - - - - - - -

Communities Moderator, SOPHOS
Knowledge Base | @SophosSupport | Video tutorials
Remember to like a post. If a post (on a question thread) solves your question use the 'This helped me' link.
Cancel
Vote Up 0 Vote Down

Cancel
0 WorEen over 7 years ago in reply to ruckus

Hi Ruckus,

Many thanks for this which is much appreciated.

Ian.
Cancel
Vote Up 0 Vote Down

Cancel
0 isoffice over 7 years ago in reply to WorEen

Hi Ian,

Have you heard anything back from Sophos Support on this issue? I have submitted extracts to them from the Remote Management System Router Logs which bear some similarity to those you submitted, but I haven't had any response, even to acknowledge their receipt.

Many thanks,

John P

2 x SG450 (Version 9.714-4)

HA = Active-Passive
Cancel
Vote Up 0 Vote Down

Cancel
0 isoffice over 7 years ago in reply to isoffice

Hi all,

I have been comparing Registry settings on a PC displayed as 'disconnected' in SEC against one shown as 'connected'.

One difference I can see is in HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Sophos\Messaging System\Router. On a PC shown as 'connected' the entry HostIPToParent is displayed as a REG_DWORD value of 0x0a3f0f37 (171904823) or similar (differs slightly on 'connected' PCs).

However, on all 'disconnected' PCs, this entry is shown as a REG_DWORD value of 0x00000000 (0).

I have no idea if this is relevant to this issue, but thought I'd highlight it anyway.

Best regards,

John P

2 x SG450 (Version 9.714-4)

HA = Active-Passive
Cancel
Vote Up 0 Vote Down

Cancel
0 QC over 7 years ago in reply to isoffice
Hello John P, Ian, and other interested parties,

(I thought I've done so but) I've not yet explicitly said that verbose logging showed that

the adapter is considered already active (otherwise a check-loop is entered)

the first call to IPAddressSet::InitialiseWithHost() correctly adds both localhost and the actual IP4 address

either Resolving the root object adapter... or Creating MessageRouter CORBA object... take localhost as resolved IP

Unless there some additional debugging option (which Support would have to reveal) further attempts from our (your) side to find or help in finding the prime reason are purportless (but perhaps educating). Inspecting other logs, network traces, registry and other comparisons will just show the (expected) consequences of the incorrectly set IOR - not why it has been incorrectly set in the first place. Development should know what happens at this point (and if necessary how to obtain actually helpful information).
Even if you are able to find the cause on your own you'd likely have only the option to work around until RMS is updated: Delayed start, service restart, adapter disable/enable. IMO the first has the least side-effects.

You can check the status of your case at Sophserv.

Christian
Cancel
Vote Up 0 Vote Down

Cancel
0 WorEen over 7 years ago in reply to isoffice

Hi John,

Our last correspondence with Sophos was on Thursday evening when they advised that this issue had been escalated to one of the Level 2 Escalation Engineers. This morning we emailed Sophos for an update and, to be honest, complain on the basis they only ever appear to respond when prompted. The outcome of this is that an engineer is now reviewing the escalation note and that this may include speaking to the Sophos GES/DEV team on our behalf. Once again we referred them to this thread.

Ian.
Cancel
Vote Up 0 Vote Down

Cancel

Reply

0 WorEen over 7 years ago in reply to isoffice

Hi John,

Our last correspondence with Sophos was on Thursday evening when they advised that this issue had been escalated to one of the Level 2 Escalation Engineers. This morning we emailed Sophos for an update and, to be honest, complain on the basis they only ever appear to respond when prompted. The outcome of this is that an engineer is now reviewing the escalation note and that this may include speaking to the Sophos GES/DEV team on our behalf. Once again we referred them to this thread.

Ian.
Cancel
Vote Up 0 Vote Down

Cancel

Children

0 isoffice over 7 years ago in reply to WorEen

Cheers Ian,

Thanks for the update. If I hear anything back on my end, I'll keep you posted.

Best regards,

John P

2 x SG450 (Version 9.714-4)

HA = Active-Passive
Cancel
Vote Up 0 Vote Down

Cancel