Thread Info
  • State Not Answered
  • Locked Locked
  • Replies 11 replies
  • Subscribers 3 subscribers
  • Views 3550 views
  • Users 0 members are here
Options
Suggested
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

relay server setup very slow

Daniel Gebler

Hello Guys,

 

I am struggling a bit with a relay setup. Have the main console with 6 relays being connected to it. 2 of which have a few thousand clients each. All relays are Win2012 servers, but the msg traffic seems to be very slow.

 

A newly installed client would keep the cert request for like 20 minutes in some cases easily. Have not seen vastly quicker clients to be honest.

 

Is there any checklist I could follow to troubleshoot?

 

Many thanks,

DanZi



This thread was automatically locked due to age.
  • 0

    Hello DanZi,

    the cert request is granted by the management server thus it's not necessarily the relay causing the delay. Or do you see the slowness only with these two relays?

    Is there a high CPU usage by RouterNT.exe? As the article mentions this could be caused by built up message files. 

    Christian

  • 0 in reply to QC

    Hi Christian,

     

    No, Router is ok, message buildup is minimal. 

     

    I would assume that the cert request message would be very quick to reach the server from the client... and then processed there. But even if the queue on the management server would be clogged, the message delivery from the client - via the relay -  to the management server should be quick, or am I mistaken there?

    There is no envelopes on the management server at all in the queue.

    Only 58 on one relay, which I would say - not a huge amount. 39 on the other, and 10 messages on the 3rd relay. 

    Management server has only one NIC with one IP address. But the relays have all 2 NICs, although it does work overall, only messages are slow and status updates to the console...

  • 0 in reply to Daniel Gebler

    Hello DanZi,

    from the server's POV there is no such thing as a dedicated message relay.
    In an endpoints-only configuration a computer establishes a (permanent TCP) connection to the server's port 8194. An endpoint's local Agent receives messages from the various components, passes them to the Router that sends them over the connection to the server's Router that in turn passes them to the server's Agent that eventually supplies them to the management components (EM and CM - the Certification Manager).
    In the general case a Router listens for messages on its port 8194 and, depending on the "routing information", supplies it to a local listener (the Agent) or its upstream, Parent Router or a another, downstream Router. Note that any Router forwards messages in this manner, i.e. any endpoint (except the management server) can act as a relay. Consequently there's no "fast lane" for relays. Relays don't reduce the traffic to the management server, just the number of TCP connections it has to handle.

    client would keep the cert request for like 20 minutes
    from where is this information? The endpoint's Agent or Router logs? As there is no obvious bottleneck the question is where the apparent delay is incurred.

    Christian

  • 0 in reply to QC

    Hi Christian,

    I am reinstalling a few broken clients and the first message that gets generated on the endpoint is the cert request. Now, that sits on the client machine for a looong time, up to 15-20 minutes easily.

    This makes it a bit difficult to identify whether the client remediation is successful.

    The router's log on the client doesn't seem to have any apparent errors, the router xml also correctly reports the relay and then eventually everything goes through fine, but considering the resources each components of the management backend has, it should be a very fast setup - or at least that is the expectation. 

    Instead of having thousands (8-9k) of clients hanging on a single 2008R2 server (I know...) now it's 4 machines, plenty of computing power, no buildup of messages, not even in the 100's measures. Comparing to the previously mentioned setup where a single policy change would clog the management server for 3 days with 99% cpu on RouterNT.exe...

     

  • 0 in reply to Daniel Gebler

    Hello DanZi,

    router's log on the client doesn't seem to have any apparent errors
    not necessarily (apparent) errors but this log is the start. A virgin Router connects to its Parent (this part apparently succeeds), sends a UniqueTokenRequest to the Certification Manager (CM) that responds with an unique token. Then the Router sends a CertRequest and (hopefully) a Certificate response:success. The Router then logs off and on again (both the Parent and the local Agent) and subsequently the Agent sends a  via the Router to CM. As you surmise each step normally takes at most a few seconds.
    It looks like this (endpoint Router log, server Router log, server CM log):

    25.09.2019 08:24:24 1260 I Current certificate name is
    25.09.2019 08:24:24 1260 I Sending unique token request...
    25.09.2019 08:24:24 22A0 I Logged on Router$NewEndpoint:0 for certification
    25.09.2019 08:24:24 1F64 I Routing to CM: id=018B0818, origin=Router$SophosEM.Router$NewEndpoint:0, dest=CM, type=Certification.UniqueTokenRequest
    25.09.2019 08:24:24 0F58 W Expanded Envelope, id=018B0818, type=Certification.UniqueTokenRequest, no Originator Cert
    25.09.2019 08:24:24 0F58 I Supplying message (id=018B0818) to CM
    25.09.2019 08:24:24 09B8 I [Msgr]Received new message:mid=18B0818:type=Certification.UniqueTokenRequest:orig=Router$SophosEM.Router$NewEndpoint:0
    25.09.2019 08:24:24 09B8 I [Msgr]Sent UniqueToken resp:to=Router$SophosEM.Router$NewEndpoint:0:reqmid=18B0818:tok=429043:respmid=38B0818
    25.09.2019 08:24:24 09B8 I [Msgr]Acknowledged message:mid=18B0818
    25.09.2019 08:24:24 1F64 I Routing to Router$NewEndpoint:0: id=038B0818, origin=Router$SophosEM.CM, dest=Router$SophosEM.Router$NewEndpoint:0, type=Certification.UniqueTokenResponse
    25.09.2019 08:24:25 1260 I Got unique token: 429043
    25.09.2019 08:24:25 1260 I New certificate name is Router$NewEndpoint:429043
    25.09.2019 08:24:25 1260 I Creating cryptographic key pair
    25.09.2019 08:24:26 1F64 I Routing to CM: id=018B081A, origin=Router$SophosEM.Router$NewEndpoint:0, dest=CM, type=Certification.CertRequest
    25.09.2019 08:24:26 1D70 W Expanded Envelope, id=018B081A, type=Certification.CertRequest, no Originator Cert
    25.09.2019 08:24:26 1D70 I Supplying message (id=018B081A) to CM
    25.09.2019 08:24:26 09B8 I [Msgr]Received new message:mid=18B081A:type=Certification.CertRequest:orig=Router$SophosEM.Router$NewEndpoint:0
    25.09.2019 08:24:26 09B8 I [CA]Issued public key certificate:subject=CN=Router$NewEndpoint:429043:serialNo=142941:requestId=30535
    25.09.2019 08:24:26 09B8 I [Msgr]Sent Certificate response:success:to=Router$SophosEM.Router$NewEndpoint:0:mid=38B081A:requestId=30535
    25.09.2019 08:24:26 09B8 I [Msgr]Acknowledged message:mid=18B081A
    25.09.2019 08:24:26 1F64 I Routing to Router$NewEndpoint:0: id=038B081A, origin=Router$SophosEM.CM, dest=Router$SophosEM.Router$NewEndpoint:0, type=Certification.CertResponse
    25.09.2019 08:24:27 1260 I Installing new router certificate...
    25.09.2019 08:24:28 1260 I Compliant certificate hashing algorithm.
    25.09.2019 08:24:28 1260 I This computer is part of the workgroup WORKGROUP
    ....
    25.09.2019 08:24:28 1260 I Waiting for messages...
    25.09.2019 08:24:28 1260 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 4, max number of user ports 15360
    25.09.2019 08:24:28 0E80 I Getting parent router IOR from 123.45.67.89:8192
    ....
    25.09.2019 08:24:28 0E80 I Received parent router's IOR:
    IOR:0100000026000000.....
    25.09.2019 08:24:28 0E80 I Successfully validated parent router's IOR
    25.09.2019 08:24:28 0E80 I Accessing parent
    25.09.2019 08:24:28 0E80 I SSL handshake done, local IP address = 10.10.10.10
    25.09.2019 08:24:28 0E80 I Parent is Router$SophosEM
    25.09.2019 08:24:28 0E80 I Registered with parent router
    25.09.2019 08:24:28 0E80 I RouterTableEntry::LogonToParentRouter() - logging on as active consumer
    25.09.2019 08:24:28 0E80 I RouterTableEntry state (router, logging on): Router$SophosEM is passive consumer, passive supplier
    25.09.2019 08:24:28 1D70 I Logged off Router$NewEndpoint:0
    25.09.2019 08:24:28 1D70 I Writing router table file
    25.09.2019 08:24:28 1F64 I Routing to EM: id=018B081C, origin=Router$SophosEM, dest=EM, type=EM-RouterRegistered
    25.09.2019 08:24:28 1B74 I Sent message (id=018B081C) to EM
    25.09.2019 08:24:28 1D70 I Registered router Router$NewEndpoint:429043
    25.09.2019 08:24:28 22A0 I RouterTableEntry state (router, logging on): Router$NewEndpoint:429043 is active consumer (will try to notify), active supplier
    25.09.2019 08:24:28 22A0 I Logged on Router$NewEndpoint:429043 as a router
    25.09.2019 08:24:28 1F64 I Routing to EM: id=038B081C, origin=Router$SophosEM, dest=EM, type=EM-RouterLogon
    25.09.2019 08:24:28 0FB4 I Sent message (id=038B081C) to EM
    25.09.2019 08:24:28 0E80 I Logged on to parent router as Router$NewEndpoint:429043
    25.09.2019 08:24:28 0E80 I This computer is part of the workgroup WORKGROUP
    25.09.2019 08:24:30 07A0 I Logged on Agent for certification
    25.09.2019 08:24:31 0C84 I Routing to parent: id=038B081F, origin=Router$NewEndpoint:429043.Agent, dest=CM, type=Certification.CertRequest
    25.09.2019 08:24:31 08D0 W Expanded Envelope, id=038B081F, type=Certification.CertRequest, no Originator Cert
    25.09.2019 08:24:31 08D0 I Sent message (id=038B081F) to Router$SophosEM
    25.09.2019 08:24:31 1F64 I Routing to CM: id=038B081F, origin=Router$NewEndpoint:429043.Agent, dest=CM, type=Certification.CertRequest
    25.09.2019 08:24:31 22A0 W Expanded Envelope, id=038B081F, type=Certification.CertRequest, no Originator Cert
    25.09.2019 08:24:31 22A0 I Supplying message (id=038B081F) to CM
    25.09.2019 08:24:31 09B8 I [Msgr]Received new message:mid=38B081F:type=Certification.CertRequest:orig=Router$NewEndpoint:429043.Agent
    25.09.2019 08:24:31 09B8 I [CA]Issued public key certificate:subject=OU=Router$NewEndpoint:429043/CN=Agent:serialNo=142942:requestId=30536
    25.09.2019 08:24:31 09B8 I [Msgr]Sent Certificate response:success:to=Router$NewEndpoint:429043.Agent:mid=18B081F:requestId=30536
    25.09.2019 08:24:31 09B8 I [Msgr]Acknowledged message:mid=38B081F
    25.09.2019 08:24:31 1F64 I Routing to Router$NewEndpoint:429043: id=018B081F, origin=Router$SophosEM.CM, dest=Router$NewEndpoint:429043.Agent, type=Certification.CertResponse
    25.09.2019 08:24:53 07A0 I Logged off Agent
    25.09.2019 08:24:55 07A0 I Logged on Agent for certification
    25.09.2019 08:24:58 0C84 I Routing to parent: id=018B083A, origin=Router$NewEndpoint:429043.Agent, dest=CM, type=Certification.CertRequest
    25.09.2019 08:24:58 01E4 W Expanded Envelope, id=018B083A, type=Certification.CertRequest, no Originator Cert
    25.09.2019 08:24:58 01E4 I Sent message (id=018B083A) to Router$SophosEM
    25.09.2019 08:24:58 1F64 I Routing to CM: id=018B083A, origin=Router$NewEndpoint:429043.Agent, dest=CM, type=Certification.CertRequest
    25.09.2019 08:24:58 0F58 W Expanded Envelope, id=018B083A, type=Certification.CertRequest, no Originator Cert
    25.09.2019 08:24:58 0F58 I Supplying message (id=018B083A) to CM
    25.09.2019 08:24:58 09B8 I [Msgr]Received new message:mid=18B083A:type=Certification.CertRequest:orig=Router$NewEndpoint:429043.Agent
    25.09.2019 08:24:58 09B8 I [CA]Issued public key certificate:subject=OU=Router$NewEndpoint:429043/CN=Agent:serialNo=142943:requestId=30537
    25.09.2019 08:24:58 09B8 I [Msgr]Sent Certificate response:success:to=Router$NewEndpoint:429043.Agent:mid=18B083A:requestId=30537
    25.09.2019 08:24:58 09B8 I [Msgr]Acknowledged message:mid=18B083A
    25.09.2019 08:24:58 1F64 I Routing to Router$NewEndpoint:429043: id=018B083A, origin=Router$SophosEM.CM, dest=Router$NewEndpoint:429043.Agent, type=Certification.CertResponse
    25.09.2019 08:26:28 0C84 I Routing to Agent: id=018B081F, origin=Router$SophosEM.CM, dest=Router$NewEndpoint:429043.Agent, type=Certification.CertResponse
    25.09.2019 08:26:28 0C84 I Routing to Agent: id=018B083A, origin=Router$SophosEM.CM, dest=Router$NewEndpoint:429043.Agent, type=Certification.CertResponse
    25.09.2019 08:26:28 1310 I Logged off Agent
    25.09.2019 08:26:29 09E4 I Writing router table file
    25.09.2019 08:26:29 09E4 I Registered client Agent
    25.09.2019 08:26:29 1310 I Client::LogonPushPush() successfully called back to client
    25.09.2019 08:26:29 1310 I Logged on Agent as a client
    25.09.2019 08:26:29 0C84 I Routing to parent: id=018B0895, origin=Router$CP179:429043.Agent, dest=EM, type=EM-EntityEvent

    You see that near the end the first CertResponse to the Agent is delayed and delivered together with the second after 90 seconds or so. The Agent was busy with initial component adapter configuration and related tasks. All in all it takes 2 minutes for the endpoint to register and send its first EM-EntityEvent.
    This is without a relay to keep it, err, short [;)]

    When a Relay is involved you can track the message flow using timestamps, computername, and message ids (note the latter aren't globally unique, i.e. two or more computers could generate messages with the same id) as marker. A typical flow through a Relay looks like this (server Router log, relay router log):

    24.09.2019 13:27:36 091C I Logged on Router$NewEndpoint:0 for certification
    24.09.2019 13:27:36 1314 I Routing to parent: id=0189FDA8, origin=Router$SophosRelay:237358.Router$NewEndpoint:0, dest=CM, type=Certification.UniqueTokenRequest
    24.09.2019 13:27:36 058C W Expanded Envelope, id=0189FDA8, type=Certification.UniqueTokenRequest, no Originator Cert
    24.09.2019 13:27:36 058C I Sent message (id=0189FDA8) to Router$SophosEM
    24.09.2019 13:27:36 1314 I Routing to Router$NewEndpoint:0: id=0189FDA8, origin=Router$SophosEM.CM, dest=Router$SophosRelay:237358.Router$NewEndpoint:0, type=Certification.UniqueTokenResponse
    24.09.2019 13:27:36 1748 I Routing to CM: id=0189FDA8, origin=Router$SophosRelay:237358.Router$NewEndpoint:0, dest=CM, type=Certification.UniqueTokenRequest
    24.09.2019 13:27:36 11A8 W Expanded Envelope, id=0189FDA8, type=Certification.UniqueTokenRequest, no Originator Cert
    24.09.2019 13:27:36 11A8 I Supplying message (id=0189FDA8) to CM
    24.09.2019 13:27:36 1748 I Routing to Router$SophosRelay:237358: id=0189FDA8, origin=Router$SophosEM.CM, dest=Router$SophosRelay:237358.Router$NewEndpoint:0, type=Certification.UniqueTokenResponse
    24.09.2019 13:27:36 22A4 I Supplying message (id=0189FDA8) to Router$SophosRelay:237358
    24.09.2019 13:27:36 1314 I Routing to Router$NewEndpoint:0: id=0189FDA8, origin=Router$SophosEM.CM, dest=Router$SophosRelay:237358.Router$NewEndpoint:0, type=Certification.UniqueTokenResponse
    24.09.2019 13:27:37 1314 I Routing to parent: id=0189FDA9, origin=Router$SophosRelay:237358.Router$NewEndpoint:0, dest=CM, type=Certification.CertRequest
    24.09.2019 13:27:37 11DC W Expanded Envelope, id=0189FDA9, type=Certification.CertRequest, no Originator Cert
    24.09.2019 13:27:37 11DC I Sent message (id=0189FDA9) to Router$SophosEM
    24.09.2019 13:27:37 1748 I Routing to CM: id=0189FDA9, origin=Router$SophosRelay:237358.Router$NewEndpoint:0, dest=CM, type=Certification.CertRequest
    24.09.2019 13:27:37 22A4 W Expanded Envelope, id=0189FDA9, type=Certification.CertRequest, no Originator Cert
    24.09.2019 13:27:37 22A4 I Supplying message (id=0189FDA9) to CM
    24.09.2019 13:27:37 1748 I Routing to Router$SophosRelay:237358: id=0189FDA9, origin=Router$SophosEM.CM, dest=Router$SophosRelay:237358.Router$NewEndpoint:0, type=Certification.CertResponse
    24.09.2019 13:27:37 2250 I Supplying message (id=0189FDA9) to Router$SophosRelay:237358
    24.09.2019 13:27:37 1314 I Routing to Router$NewEndpoint:0: id=0189FDA9, origin=Router$SophosEM.CM, dest=Router$SophosRelay:237358.Router$NewEndpoint:0, type=Certification.CertResponse
    24.09.2019 13:27:38 091C I Logged off Router$NewEndpoint:0
    24.09.2019 13:27:38 11B4 I Writing router table file
    24.09.2019 13:27:38 1314 I Routing to parent: id=0189FDAA, origin=Router$SophosRelay:237358, dest=EM, type=EM-RouterRegistered
    24.09.2019 13:27:38 11B4 I Registered router Router$NewEndpoint:429021
    24.09.2019 13:27:38 1314 I Routing to parent: id=0389FDAA, origin=Router$SophosRelay:237358, dest=:.:, type=MS-RouterRegistered
    24.09.2019 13:27:38 07CC I RouterTableEntry state (router, logging on): Router$NewEndpoint:429021 is active consumer (will try to notify), active supplier
    24.09.2019 13:27:38 07CC I Logged on Router$NewEndpoint:429021 as a router
    24.09.2019 13:27:38 1314 I Routing to parent: id=0589FDAA, origin=Router$SophosRelay:237358, dest=EM, type=EM-RouterLogon
    24.09.2019 13:27:38 0D1C I Sent message (id=0189FDAA) to Router$SophosEM
    24.09.2019 13:27:38 0D1C I Sent message (id=0389FDAA) to Router$SophosEM
    24.09.2019 13:27:38 0D1C I Sent message (id=0589FDAA) to Router$SophosEM
    24.09.2019 13:27:38 1748 I Routing to EM: id=0189FDAA, origin=Router$SophosRelay:237358, dest=EM, type=EM-RouterRegistered
    24.09.2019 13:27:38 1D40 I Sent message (id=0189FDAA) to EM
    24.09.2019 13:27:38 1748 I Received message for this router
    24.09.2019 13:27:38 1748 I MS-RouterRegistered - router has no logical routing table originator Router$SophosRelay:237358
    24.09.2019 13:27:38 1748 I Routing to EM: id=0589FDAA, origin=Router$SophosRelay:237358, dest=EM, type=EM-RouterLogon
    24.09.2019 13:27:38 1A90 I Sent message (id=0589FDAA) to EM
    24.09.2019 13:27:43 1314 I Routing to parent: id=0389FDAF, origin=Router$NewEndpoint:429021.Agent, dest=CM, type=Certification.CertRequest
    24.09.2019 13:27:43 0F68 W Expanded Envelope, id=0389FDAF, type=Certification.CertRequest, no Originator Cert
    24.09.2019 13:27:43 0F68 I Sent message (id=0389FDAF) to Router$SophosEM
    24.09.2019 13:27:43 1748 I Routing to CM: id=0389FDAF, origin=Router$SophosRelay:237358.Router$NewEndpoint:429021.Agent, dest=CM, type=Certification.CertRequest
    24.09.2019 13:27:43 2250 W Expanded Envelope, id=0389FDAF, type=Certification.CertRequest, no Originator Cert
    24.09.2019 13:27:43 2250 I Supplying message (id=0389FDAF) to CM
    24.09.2019 13:27:43 1748 I Routing to Router$SophosRelay:237358: id=0189FDAF, origin=Router$SophosEM.CM, dest=Router$SophosRelay:237358.Router$NewEndpoint:429021.Agent, type=Certification.CertResponse
    24.09.2019 13:27:44 11A8 I Supplying message (id=0189FDAF) to Router$SophosRelay:237358
    24.09.2019 13:27:44 1314 I Routing to Router$NewEndpoint:429021: id=0189FDAF, origin=Router$SophosEM.CM, dest=Router$SophosRelay:237358.Router$NewEndpoint:429021.Agent, type=Certification.CertResponse

    I hope you get an idea how it's supposed to work and the examples help you to figure out where this process is delayed. Please note that on a router with many endpoints their messages are naturally intermingled.

    Christian 

  • 0 in reply to QC

    Wow, nice one Christian! Many thanks for this.

     

    I'll try to track the next few clients this way and see where the delay is at.

  • 0 in reply to Daniel Gebler

    Hi Christian, 

    I have tracked a few machines throughout the day.

     

    Seems that the initial cert request times out, but subsequent request is ok.  Not sure if I read the log correctly, but seems that the cert request gets generated at 15:57, then gets routed twice. Some lines are omitted (I just filtered for the HOSTNAME in all three logs)

    There seems to be quite a long time before the server replies with the cert response, and it takes just the same time... 15-20 mins for a client to appear in the console...

     

     

    HOST 
    27.09.2019 15:57:37 1838 I New certificate name is Router$<HOSTNAME>:54974
    27.09.2019 15:57:40 1838 I Host name: <HOSTNAME>
    27.09.2019 15:57:40 1838 I Resolved name: <HOSTNAME>.<DOMAIN>
    27.09.2019 15:57:40 1838 I Resolved reverse names/aliases: <HOSTNAME>.<DOMAIN>
    27.09.2019 15:57:46 1A1C I Routing to parent: id=038E155A, origin=Router$<HOSTNAME>:54974.Agent, dest=CM, type=Certification.CertRequest
    27.09.2019 16:07:49 1A1C I Routing to parent: id=018E17B5, origin=Router$<HOSTNAME>:54974.Agent, dest=CM, type=Certification.CertRequest
    27.09.2019 16:08:10 0810 W Delivery failed(Timeout) for message type Certification.CertRequest, originator Router$<HOSTNAME>:54974.Agent
    27.09.2019 16:08:21 0B30 I Logged on to parent router as Router$<HOSTNAME>:54974
    27.09.2019 16:16:02 1A1C I Routing to Agent: id=018E1916, origin=Router$<RELAY>:27017.Router$<MANAGEMENT>.CM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:54974.Agent,
    type=Certification.CertResponse
    27.09.2019 16:16:03 1A1C I Routing to parent: id=018E19A3, origin=Router$<HOSTNAME>:54974.Agent, dest=EM, type=EM-EntityEvent
    27.09.2019 16:16:03 1A1C I EM-NotifyClientUpdates originator Router$<HOSTNAME>:54974.Agent
    27.09.2019 16:16:03 1A1C I Routing to parent: id=058E19A3, origin=Router$<HOSTNAME>:54974.Agent, dest=EM, type=EM-EntityEvent
    27.09.2019 16:16:03 1A1C I Routing to Agent: id=078E19A3, origin=Router$<HOSTNAME>:54974, dest=Router$<HOSTNAME>:54974.Agent, type=EM-NotifyClientUpdates-Reply
     
    RELAY
    27.09.2019 15:56:54 1B14 I Logged on Router$<HOSTNAME>:0 for certification
    27.09.2019 15:57:15 1658 I Routing to parent: id=018E153B, origin=Router$<RELAY>:27017.Router$<HOSTNAME>:0, dest=CM, type=Certification.UniqueTokenRequest
    27.09.2019 15:57:15 1658 I Routing to Router$<HOSTNAME>:0: id=018E153B, origin=Router$<MANAGEMENT>.CM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:0, type=Certification.UniqueTokenResponse
    27.09.2019 15:57:38 1658 I Routing to parent: id=018E1552, origin=Router$<RELAY>:27017.Router$<HOSTNAME>:0, dest=CM, type=Certification.CertRequest
    27.09.2019 15:57:38 1658 I Routing to Router$<HOSTNAME>:0: id=018E1552, origin=Router$<MANAGEMENT>.CM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:0, type=Certification.CertResponse
    27.09.2019 15:57:39 0404 I Logged off Router$<HOSTNAME>:0
    27.09.2019 16:08:21 1B14 I Registered router Router$<HOSTNAME>:54974
    27.09.2019 16:08:21 1B14 I RouterTableEntry state (router, logging on): Router$<HOSTNAME>:54974 is active consumer (will try to notify), active supplier
    27.09.2019 16:08:21 1B14 I Logged on Router$<HOSTNAME>:54974 as a router
    27.09.2019 16:13:42 1658 I Routing to parent: id=018E17B5, origin=Router$<HOSTNAME>:54974.Agent, dest=CM, type=Certification.CertRequest
    27.09.2019 16:13:42 1658 I Routing to Router$<HOSTNAME>:54974: id=018E1916, origin=Router$<MANAGEMENT>.CM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:54974.Agent,
    type=Certification.CertResponse
    27.09.2019 16:16:02 0518 I Supplying message (id=018E1916) to Router$<HOSTNAME>:54974
    27.09.2019 16:16:03 1658 I Routing to parent: id=018E19A3, origin=Router$<HOSTNAME>:54974.Agent, dest=EM, type=EM-EntityEvent
    27.09.2019 16:16:03 1658 I Routing to parent: id=058E19A3, origin=Router$<HOSTNAME>:54974.Agent, dest=EM, type=EM-EntityEvent
    27.09.2019 16:16:23 1658 I Routing to parent: id=018E19B7, origin=Router$<HOSTNAME>:54974.Agent, dest=EM, type=EM-GetStatus-Reply
    27.09.2019 16:16:24 1658 I Routing to Router$<HOSTNAME>:54974: id=018E19B8, origin=Router$<MANAGEMENT>.EM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:54974.Agent, type=EM-SetConfiguration
    27.09.2019 16:16:24 1658 I Routing to Router$<HOSTNAME>:54974: id=038E19B8, origin=Router$<MANAGEMENT>.EM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:54974.Agent, type=EM-SetConfiguration
    27.09.2019 16:16:24 1658 I Routing to Router$<HOSTNAME>:54974: id=058E19B8, origin=Router$<MANAGEMENT>.EM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:54974.Agent, type=EM-SetConfiguration
    27.09.2019 16:16:24 1658 I Routing to Router$<HOSTNAME>:54974: id=078E19B8, origin=Router$<MANAGEMENT>.EM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:54974.Agent, type=EM-SetConfiguration
    27.09.2019 16:16:24 1658 I Routing to Router$<HOSTNAME>:54974: id=098E19B8, origin=Router$<MANAGEMENT>.EM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:54974.Agent, type=EM-SetConfiguration
     
    MANAGEMENT SERVER
    27.09.2019 15:57:15 1D60 I Routing to CM: id=018E153B, origin=Router$<RELAY>:27017.Router$<HOSTNAME>:0, dest=CM, type=Certification.UniqueTokenRequest
    27.09.2019 15:57:15 1D60 I Routing to Router$<RELAY>:27017: id=018E153B, origin=Router$<MANAGEMENT>.CM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:0, type=Certification.UniqueTokenResponse
    27.09.2019 15:57:38 1D60 I Routing to CM: id=018E1552, origin=Router$<RELAY>:27017.Router$<HOSTNAME>:0, dest=CM, type=Certification.CertRequest
    27.09.2019 15:57:38 1D60 I Routing to Router$<RELAY>:27017: id=018E1552, origin=Router$<MANAGEMENT>.CM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:0, type=Certification.CertResponse
    27.09.2019 16:13:42 1D60 I Routing to CM: id=018E17B5, origin=Router$<RELAY>:27017.Router$<HOSTNAME>:54974.Agent, dest=CM, type=Certification.CertRequest
    27.09.2019 16:13:42 1D60 I Routing to Router$<RELAY>:27017: id=018E1916, origin=Router$<MANAGEMENT>.CM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:54974.Agent, type=Certification.CertResponse

  • 0 in reply to Daniel Gebler

    Hello DanZi,

    a q&d late Friday assessment:
    Router registration (token and cert) works as it should. In my example I showed that subsequently the Router on the endpoint should log off from the initial connection and log on as certified router. The log off is reflected on the Relay but the expected reconnect is only after ten minutes:
    27.09.2019 15:57:39 0404 I Logged off Router$<HOSTNAME>:0
    27.09.2019 16:08:21 1B14 I Registered router Router$<HOSTNAME>:54974
    What's going on at this time should be in the endpoint (HOST) log - if there is some useful message.

    The Agent's CertRequest (018E17B5) is delayed for more than 5 minutes from HOST to RELAY
    27.09.2019 16:08:21 1B14 I Logged on Router$<HOSTNAME>:54974 as a router
    27.09.2019 16:13:42 1658 I Routing to parent: id=018E17B5, origin=Router$<HOSTNAME>:54974.Agent, dest=CM, type=Certification.CertRequest
    but is then immediately forwarded to and responded by CM. The response in turn is delayed on the Relay
    27.09.2019 16:13:42 1658 I Routing to Router$<HOSTNAME>:54974: id=018E1916, origin=Router$<MANAGEMENT>.CM, dest=Router$<RELAY>:27017.Router$<HOSTNAME>:54974.Agent,
    type=Certification.CertResponse
    27.09.2019 16:16:02 0518 I Supplying message (id=018E1916) to Router$<HOSTNAME>:54974

    This looks like communication is slow or suffers from the delays when TLS is used. If the endpoint's Router log doesn't show anomalies then Wireshark is your friend.

    Christian

  • 0 in reply to QC

    Christian, many thanks for the analysis, I will get hold of a few other machines and replicate this. 

     

  • 0 in reply to Daniel Gebler

    Hi Christian,

     

    Got hold of some logs for another machine. 

     

    What I noticed is that the client 'sits' on 2 messages, trying to get them out, there's a delay warning. Then when the server sends messages, the realy takes 14 mins to pass them on to the client...

    Added some notes in red below.

    The client is online all the time and there are no envelopes buildup anywhere. Like 40-100 messages in the queue folder on the relay, which is 'peanuts'...

     

    Daniel

     

    Client:

     

    07.11.2019 10:31:46 15EC I SOF: C:\ProgramData/Sophos/Remote Management System/3/Router/Logs/Router-20191107-093146.log

    07.11.2019 10:31:46 15EC I Sophos Messaging Router 4.1.1.127 starting...

    07.11.2019 10:31:46 15EC I Setting ACE_FD_SETSIZE to 138

    07.11.2019 10:31:46 15EC I Initializing CORBA...

    07.11.2019 10:31:46 15EC I Connection cache limit is 10

    07.11.2019 10:31:46 15EC I Router::ConfigureSslContext: keeping legacy compatibility of TLS 1 and TLS 1.1.

    07.11.2019 10:31:46 15EC I Creating ORB runner with 4 threads

    07.11.2019 10:31:46 15EC W No public key certificate found in the store. Requesting a new certificate.

    07.11.2019 10:31:46 15EC I Getting parent router IOR from <Relay IP Address>:8192

    07.11.2019 10:31:46 15EC I This computer is part of the domain <Domain>

    07.11.2019 10:31:46 15EC I Getting a new router certificate...

    07.11.2019 10:32:07 15EC I SSL handshake done, local IP address = <Client IP Address>

    07.11.2019 10:32:28 15EC I Current certificate name is

    07.11.2019 10:32:28 15EC I Sending unique token request...

    07.11.2019 10:33:11 15EC I Got unique token: 81509

    07.11.2019 10:33:11 15EC I New certificate name is Router$<Client Hostname>:81509

    07.11.2019 10:33:11 15EC I Creating cryptographic key pair

    07.11.2019 10:33:13 15EC I Installing new router certificate...

    07.11.2019 10:33:14 15EC I Compliant certificate hashing algorithm.

    07.11.2019 10:33:14 15EC I This computer is part of the domain <Domain>

    07.11.2019 10:33:14 15EC I This router's IOR:

    IOR:010000002600000049444c3a536f70686f734d6573736167696e672f4d657373616765526f757465723a312e300000000100000000000000a4000000010102000d00000031302e302e3233392e323031000001204100000014010f004e5550000000210000000001000000526f6f74504f4100526f7574657250657273697374656e740003000000010000004d657373616765526f757465720000000300000000000000080000000100ab00004f415401000000180000000100ab00010001000100000001000105090101000000000014000000080000000100a60086000420

    07.11.2019 10:33:14 15EC I Successfully validated this router's IOR

    07.11.2019 10:33:14 15EC I Reading router table file

    07.11.2019 10:33:14 15EC I Host name: <Client Hostname>

    07.11.2019 10:33:14 15EC I Local IP addresses: <Client IP Address>

    07.11.2019 10:33:14 15EC I Resolved name: <Client Hostname>.<Domain>.<domain suffix>

    07.11.2019 10:33:14 15EC I Resolved alias/es:

    07.11.2019 10:33:14 15EC I Resolved IP addresses: <Client IP Address>

    07.11.2019 10:33:14 15EC I Resolved reverse names/aliases: <Client Hostname>.<Domain>.<domain suffix>

    07.11.2019 10:33:14 388C I Routing to parent: id=01C3E437, origin=Router$<Client Hostname>:81387, dest=Router$<Client Hostname>:81387.Agent, type=EM-ClientLogoff

    07.11.2019 10:33:14 15EC I Waiting for messages...

    07.11.2019 10:33:14 15EC I RouterSystemCheck::onInfoPortsUsed() - number of user ports 5, max number of user ports 15360

    07.11.2019 10:33:14 3A68 I Getting parent router IOR from <Relay IP Address>:8192

    07.11.2019 10:33:14 3A68 I Received parent router's IOR:

    IOR:010000002600000049444c3a536f70686f734d6573736167696e672f4d657373616765526f757465723a312e300000000200000000000000a4000000010102000e00000031302e3137302e34382e3132340001204100000014010f004e5550000000210000000001000000526f6f74504f4100526f7574657250657273697374656e740003000000010000004d657373616765526f7574657200000003000000000000000800000001005501004f4154010000001800000001005501010001000100000001000105090101000000000014000000080000000100a6008600042000000000a4000000010102000e00000031302e3136382e34382e3132340001204100000014010f004e5550000000210000000001000000526f6f74504f4100526f7574657250657273697374656e740003000000010000004d657373616765526f7574657200000003000000000000000800000001005501004f4154010000001800000001005501010001000100000001000105090101000000000014000000080000000100a60086000420

    07.11.2019 10:33:14 3A68 I Successfully validated parent router's IOR

    07.11.2019 10:33:14 3A68 I Accessing parent

    07.11.2019 10:33:18 0C6C I Logged on Agent for certification

    07.11.2019 10:33:19 388C I Routing to parent: id=03C3E4DF, origin=Router$<Client Hostname>:81509.Agent, dest=CM, type=Certification.CertRequest

    07.11.2019 10:38:34 3A68 I SSL handshake done, local IP address = <Client IP Address>

    07.11.2019 10:38:34 3A68 I Parent is Router$<Relay hostname>:27017

    07.11.2019 10:43:20 2FB8 I Logged off Agent

    07.11.2019 10:43:20 2FB8 I Logged on Agent for certification

    07.11.2019 10:43:22 388C I Routing to parent: id=01C3E73A, origin=Router$<Client Hostname>:81509.Agent, dest=CM, type=Certification.CertRequest

    07.11.2019 10:43:44 320C W Delivery failed(Timeout) for message type Certification.CertRequest, originator Router$<Client Hostname>:81509.Agent

    07.11.2019 10:43:54 3A68 I Registered with parent router

    07.11.2019 10:43:54 3A68 I RouterTableEntry::LogonToParentRouter() - logging on as active consumer

    07.11.2019 10:43:54 3A68 I RouterTableEntry state (router, logging on): Router$<Relay hostname>:27017 is passive consumer, passive supplier

    07.11.2019 10:43:54 3A68 I Logged on to parent router as Router$<Client Hostname>:81509

    07.11.2019 10:43:54 3A68 I This computer is part of the domain <Domain> 6 minutes delay here

    07.11.2019 10:49:14 37D8 I Sent message (id=01C3E437) to Router$<Relay hostname>:27017

    07.11.2019 10:49:14 37D8 W Expanded Envelope, id=01C3E73A, type=Certification.CertRequest, no Originator Cert

    07.11.2019 10:49:14 37D8 I Sent message (id=01C3E73A) to Router$<Relay hostname>:27017

    07.11.2019 10:52:14 388C I Routing to Agent: id=01C3E89A, origin=Router$<Relay hostname>:27017.Router$<Mgmt Server hostname>.CM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=Certification.CertResponse

    07.11.2019 10:52:15 2FB8 I Logged off Agent

    07.11.2019 10:52:15 0C6C I Writing router table file

    07.11.2019 10:52:15 0C6C I Registered client Agent

    07.11.2019 10:52:15 2FB8 I Client::LogonPushPush() successfully called back to client

    07.11.2019 10:52:15 2FB8 I Logged on Agent as a client

    07.11.2019 10:52:15 388C I Routing to parent: id=01C3E94F, origin=Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-EntityEvent

    07.11.2019 10:52:15 37D8 I Sent message (id=01C3E94F) to Router$<Relay hostname>:27017

    07.11.2019 10:52:15 388C I Received message for this router

    07.11.2019 10:52:15 388C I EM-NotifyClientUpdates originator Router$<Client Hostname>:81509.Agent

    07.11.2019 10:52:15 388C I Routing to parent: id=05C3E94F, origin=Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-EntityEvent

    07.11.2019 10:52:15 388C I Routing to Agent: id=07C3E94F, origin=Router$<Client Hostname>:81509, dest=Router$<Client Hostname>:81509.Agent, type=EM-NotifyClientUpdates-Reply

    07.11.2019 10:52:15 3230 I Sent message (id=07C3E94F) to Agent

    07.11.2019 10:52:15 25DC I Sent message (id=05C3E94F) to Router$<Relay hostname>:27017

    07.11.2019 10:52:35 388C I Routing to parent: id=01C3E963, origin=Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-GetStatus-Reply

    07.11.2019 10:52:35 37D8 I Sent message (id=01C3E963) to Router$<Relay hostname>:27017

    07.11.2019 11:06:44 388C I Routing to Agent: id=01C3E94F, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 3230 I Sent message (id=01C3E94F) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=03C3E94F, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 25DC I Sent message (id=03C3E94F) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=05C3E94F, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 37D8 I Sent message (id=05C3E94F) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=01C3E950, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 3230 I Sent message (id=01C3E950) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=03C3E950, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 25DC I Sent message (id=03C3E950) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=05C3E950, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 37D8 I Sent message (id=05C3E950) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=07C3E950, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 3230 I Sent message (id=07C3E950) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=09C3E950, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 25DC I Sent message (id=09C3E950) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=0BC3E950, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 37D8 I Sent message (id=0BC3E950) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=0DC3E950, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 3230 I Sent message (id=0DC3E950) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=01C3E964, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 25DC I Sent message (id=01C3E964) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=03C3E964, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 37D8 I Sent message (id=03C3E964) to Agent

    07.11.2019 11:06:44 388C I Routing to Agent: id=05C3E964, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:44 3230 I Sent message (id=05C3E964) to Agent

    07.11.2019 11:06:45 388C I Routing to Agent: id=07C3E964, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:45 25DC I Sent message (id=07C3E964) to Agent

    07.11.2019 11:06:45 388C I Routing to Agent: id=09C3E964, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:45 37D8 I Sent message (id=09C3E964) to Agent

    07.11.2019 11:06:45 388C I Routing to Agent: id=0BC3E964, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:45 3230 I Sent message (id=0BC3E964) to Agent

    07.11.2019 11:06:45 388C I Routing to Agent: id=0DC3E964, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:45 25DC I Sent message (id=0DC3E964) to Agent

    07.11.2019 11:06:45 388C I Routing to Agent: id=0FC3E964, origin=Router$<Relay Hostname>:27017.Router$<MGMT Server Hostname>.EM, dest=Router$<Relay Hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:06:45 37D8 I Sent message (id=0FC3E964) to Agent

    07.11.2019 11:07:27 388C I Routing to parent: id=01C3ECDF, origin=Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-GetStatus-Reply

    07.11.2019 11:07:27 3230 I Sent message (id=01C3ECDF) to Router$<Relay Hostname>:27017

    07.11.2019 11:33:14 15EC I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360

     

     

     

    Message Relay:

     

    07.11.2019 10:30:32 0CE8 I Logged off Router$<Client Hostname>:81387 - When I initiated the reinstall

    07.11.2019 10:32:28 0708 I Logged on Router$<Client Hostname>:0 for certification

    07.11.2019 10:32:49 108C I Routing to parent: id=03C3E4C1, origin=Router$<Relay hostname>:27017.Router$<Client Hostname>:0, dest=CM, type=Certification.UniqueTokenRequest

    07.11.2019 10:32:49 108C I Routing to Router$<Client Hostname>:0: id=01C3E4C1, origin=Router$<Mgmt Server hostname>.CM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:0, type=Certification.UniqueTokenResponse

    07.11.2019 10:33:12 108C I Routing to parent: id=01C3E4D8, origin=Router$<Relay hostname>:27017.Router$<Client Hostname>:0, dest=CM, type=Certification.CertRequest

    07.11.2019 10:33:12 108C I Routing to Router$<Client Hostname>:0: id=01C3E4D8, origin=Router$<Mgmt Server hostname>.CM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:0, type=Certification.CertResponse

    07.11.2019 10:33:14 0CE8 I Logged off Router$<Client Hostname>:0

    07.11.2019 10:43:54 0CA4 I Registered router Router$<Client Hostname>:81509

    07.11.2019 10:43:54 0CE8 I RouterTableEntry state (router, logging on): Router$<Client Hostname>:81509 is active consumer (will try to notify), active supplier

    07.11.2019 10:43:54 0CE8 I Logged on Router$<Client Hostname>:81509 as a router

    07.11.2019 10:49:14 108C I Routing to Router$<Client Hostname>:81387: id=01C3E437, origin=Router$<Client Hostname>:81509.Router$<Client Hostname>:81387, dest=Router$<Client Hostname>:81387.Agent, type=EM-ClientLogoff

    07.11.2019 10:49:14 108C I Routing to parent: id=01C3E73A, origin=Router$<Client Hostname>:81509.Agent, dest=CM, type=Certification.CertRequest

    07.11.2019 10:49:14 108C I Routing to Router$<Client Hostname>:81509: id=01C3E89A, origin=Router$<Mgmt Server hostname>.CM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=Certification.CertResponse

    07.11.2019 10:52:14 0CE8 I Supplying message (id=01C3E89A) to Router$<Client Hostname>:81509

    07.11.2019 10:52:15 108C I Routing to parent: id=01C3E94F, origin=Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-EntityEvent

    07.11.2019 10:52:15 108C I Routing to parent: id=05C3E94F, origin=Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-EntityEvent

    07.11.2019 10:52:16 108C I Routing to Router$<Client Hostname>:81509: id=01C3E94F, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 108C I Routing to Router$<Client Hostname>:81509: id=03C3E94F, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 108C I Routing to Router$<Client Hostname>:81509: id=05C3E94F, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 108C I Routing to Router$<Client Hostname>:81509: id=01C3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 108C I Routing to Router$<Client Hostname>:81509: id=03C3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 108C I Routing to Router$<Client Hostname>:81509: id=05C3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 108C I Routing to Router$<Client Hostname>:81509: id=07C3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 108C I Routing to Router$<Client Hostname>:81509: id=09C3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 108C I Routing to Router$<Client Hostname>:81509: id=0BC3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:17 108C I Routing to Router$<Client Hostname>:81509: id=0DC3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:35 108C I Routing to parent: id=01C3E963, origin=Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-GetStatus-Reply

    config messages arrive from management server

    07.11.2019 10:52:36 108C I Routing to Router$<Client Hostname>:81509: id=01C3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 108C I Routing to Router$<Client Hostname>:81509: id=03C3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 108C I Routing to Router$<Client Hostname>:81509: id=05C3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 108C I Routing to Router$<Client Hostname>:81509: id=07C3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 108C I Routing to Router$<Client Hostname>:81509: id=09C3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:37 108C I Routing to Router$<Client Hostname>:81509: id=0BC3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:37 108C I Routing to Router$<Client Hostname>:81509: id=0DC3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:37 108C I Routing to Router$<Client Hostname>:81509: id=0FC3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    14 min delay till they get to the client

    07.11.2019 11:06:44 0CA4 I Supplying message (id=01C3E94F) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0CA4 I Supplying message (id=03C3E94F) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0CA4 I Supplying message (id=05C3E94F) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0CA4 I Supplying message (id=01C3E950) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0CA4 I Supplying message (id=03C3E950) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0CA4 I Supplying message (id=05C3E950) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0CA4 I Supplying message (id=07C3E950) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0CA4 I Supplying message (id=09C3E950) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0710 I Supplying message (id=0BC3E950) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0710 I Supplying message (id=0DC3E950) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0708 I Supplying message (id=01C3E964) to Router$<Client Hostname>:81509

    07.11.2019 11:06:44 0CA4 I Supplying message (id=03C3E964) to Router$<Client Hostname>:81509

    07.11.2019 11:06:45 0CA4 I Supplying message (id=05C3E964) to Router$<Client Hostname>:81509

    07.11.2019 11:06:45 0CA4 I Supplying message (id=07C3E964) to Router$<Client Hostname>:81509

    07.11.2019 11:06:45 0CA4 I Supplying message (id=09C3E964) to Router$<Client Hostname>:81509

    07.11.2019 11:06:45 0708 I Supplying message (id=0BC3E964) to Router$<Client Hostname>:81509

    07.11.2019 11:06:45 0708 I Supplying message (id=0DC3E964) to Router$<Client Hostname>:81509

    07.11.2019 11:06:45 0708 I Supplying message (id=0FC3E964) to Router$<Client Hostname>:81509

    07.11.2019 11:07:27 108C I Routing to parent: id=01C3ECDF, origin=Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-GetStatus-Reply

     

     

     

     

     

    Management Server

     

    07.11.2019 10:32:49 1320 I Routing to CM: id=03C3E4C1, origin=Router$<Relay hostname>:27017.Router$<Client Hostname>:0, dest=CM, type=Certification.UniqueTokenRequest

    07.11.2019 10:32:49 1320 I Routing to Router$<Relay hostname>:27017: id=01C3E4C1, origin=Router$<Mgmt Server hostname>.CM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:0, type=Certification.UniqueTokenResponse

    07.11.2019 10:33:12 1320 I Routing to CM: id=01C3E4D8, origin=Router$<Relay hostname>:27017.Router$<Client Hostname>:0, dest=CM, type=Certification.CertRequest

    07.11.2019 10:33:12 1320 I Routing to Router$<Relay hostname>:27017: id=01C3E4D8, origin=Router$<Mgmt Server hostname>.CM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:0, type=Certification.CertResponse

    07.11.2019 10:49:14 1320 I Routing to CM: id=01C3E73A, origin=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, dest=CM, type=Certification.CertRequest

    07.11.2019 10:49:14 1320 I Routing to Router$<Relay hostname>:27017: id=01C3E89A, origin=Router$<Mgmt Server hostname>.CM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=Certification.CertResponse

    07.11.2019 10:52:15 1320 I Routing to EM: id=01C3E94F, origin=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-EntityEvent

    07.11.2019 10:52:15 1320 I Routing to EM: id=05C3E94F, origin=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-EntityEvent

    07.11.2019 10:52:15 1320 I Routing to Router$<Relay hostname>:27017: id=01C3E94F, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:15 1320 I Routing to Router$<Relay hostname>:27017: id=03C3E94F, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:15 1320 I Routing to Router$<Relay hostname>:27017: id=05C3E94F, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 1320 I Routing to Router$<Relay hostname>:27017: id=01C3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 1320 I Routing to Router$<Relay hostname>:27017: id=03C3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 1320 I Routing to Router$<Relay hostname>:27017: id=05C3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 1320 I Routing to Router$<Relay hostname>:27017: id=07C3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 1320 I Routing to Router$<Relay hostname>:27017: id=09C3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 1320 I Routing to Router$<Relay hostname>:27017: id=0BC3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:16 1320 I Routing to Router$<Relay hostname>:27017: id=0DC3E950, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:35 1320 I Routing to EM: id=01C3E963, origin=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-GetStatus-Reply

    creates a lot of config messages

    07.11.2019 10:52:36 1320 I Routing to Router$<Relay hostname>:27017: id=01C3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 1320 I Routing to Router$<Relay hostname>:27017: id=03C3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 1320 I Routing to Router$<Relay hostname>:27017: id=05C3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 1320 I Routing to Router$<Relay hostname>:27017: id=07C3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 1320 I Routing to Router$<Relay hostname>:27017: id=09C3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 1320 I Routing to Router$<Relay hostname>:27017: id=0BC3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 1320 I Routing to Router$<Relay hostname>:27017: id=0DC3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 10:52:36 1320 I Routing to Router$<Relay hostname>:27017: id=0FC3E964, origin=Router$<Mgmt Server hostname>.EM, dest=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, type=EM-SetConfiguration

    07.11.2019 11:07:27 1320 I Routing to EM: id=01C3ECDF, origin=Router$<Relay hostname>:27017.Router$<Client Hostname>:81509.Agent, dest=EM, type=EM-GetStatus-Reply

Unfiltered HTML