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

Endpoints are out-of-date in SEC but are up-to-date

Hello,

We have a Sophos Enterprise Console (SEC) v.5.2 on a Windows server 2003. The DB is a MS SQL 2008 on a Windows server 2008 R2 Standard. All the endpoints are at version 9.7.

I have been having a problem for a will with SEC. Once in a will, 40% to 60% of the endpoints shows as if they are out-of-date. As for an example, the computer details of endpoint CS1234 shows that the last successful update is 10/7/2013 12:19:41 PM. In its alc.log, I see 7 other successful updates since that date. Here is the latest one:

Time: 10/8/2013 9:19:42

Message: AutoUpdate finished

Module: ALUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:41

Message: Installation of Sophos AutoUpdate skipped

Module: ALUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:41

Message: Installation of SAVXP skipped

Module: ALUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:41

Message: Installation of RMSNT skipped

Module: ALUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:41

Message: Downloading phase completed

Module: ALUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:41

Message: Product cache update from primary server successfully finished

Module: CIDUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:41

Message: Downloading product Sophos AutoUpdate from server \\SophosServer\SophosUpdate\CIDs\S330\SAVSCFXP\

Module: CIDUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:40

Message: Product cache update from primary server successfully finished

Module: CIDUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:40

Message: Downloading product SAVXP from server \\SophosServer\SophosUpdate\CIDs\S330\SAVSCFXP\

Module: CIDUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:39

Message: Product cache update from primary server successfully finished

Module: CIDUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:39

Message: Downloading product RMSNT from server \\SophosServer\SophosUpdate\CIDs\S330\SAVSCFXP\

Module: CIDUpdate

Process ID: 1068

Thread ID: 4524

Time: 10/8/2013 9:19:39

Message: *************** Sophos AutoUpdate started ***************

Module: ALUpdate

Process ID: 1068

Thread ID: 4524

I don't see any error messages. To me, everything seems fine.

I also looked into the ALUpdate****.log file. Here is the latest update in the file:

Trace(2013-Oct-08 09:19:39): ALUpdate started: -ScheduledUpdate -NoGUI -RootPath "C:\Program Files\Sophos\AutoUpdate"
Trace(2013-Oct-08 09:19:39): Product iProductData.{390DCDC2-10A9-4ef3-B8D8-0CA7F0E7EB92} has been added.
Trace(2013-Oct-08 09:19:39): Product iProductData.{390DCDC2-10A9-4ef3-B8D8-0CA7F0E7EB92} is not available from Sophos.
Trace(2013-Oct-08 09:19:39): Product iProductData.{390DCDC2-10A9-4ef3-B8D8-0CA7F0E7EB92} is not the Spam Rules package.
Trace(2013-Oct-08 09:19:39): Product iProductData.{D752FAB9-5883-4b36-8740-61565B6BAD29} has not been added.
Trace(2013-Oct-08 09:19:39): Product iProductData.{E17FE03B-0501-4aaa-BC69-0129D965F311} has been added.
Trace(2013-Oct-08 09:19:39): Product iProductData.{E17FE03B-0501-4aaa-BC69-0129D965F311} is available from Sophos.
Trace(2013-Oct-08 09:19:39): Product iProductData.{E17FE03B-0501-4aaa-BC69-0129D965F311} is not the Spam Rules package.
Trace(2013-Oct-08 09:19:39): Product subscription is disabled: iProductData.{7998C326-2CA5-4830-B7D2-B792D2460975} action value is:0
Trace(2013-Oct-08 09:19:39): Product iProductData.{7998C326-2CA5-4830-B7D2-B792D2460975} has not been added.
Trace(2013-Oct-08 09:19:39): Product iProductData.{3B758ED7-87C1-4e89-BDE1-F49DFF1249F6} has not been added.
Trace(2013-Oct-08 09:19:39): Product iProductData.{B5E7E2A7-3B64-437D-801F-21CC9D67CC6D} has been added.
Trace(2013-Oct-08 09:19:39): Product iProductData.{B5E7E2A7-3B64-437D-801F-21CC9D67CC6D} is available from Sophos.
Trace(2013-Oct-08 09:19:39): Product iProductData.{B5E7E2A7-3B64-437D-801F-21CC9D67CC6D} is the Spam Rules package.
Trace(2013-Oct-08 09:19:39): ConfigurationImpl, considering PMSR 2.6: PureMessage not installed, PMSR package will not be updated without a subscription
Trace(2013-Oct-08 09:19:39): Considering subscribed products.
Trace(2013-Oct-08 09:19:39): Considering product {9BF40A4E-23AE-48be-9974-5A1F261DBEE8}
Trace(2013-Oct-08 09:19:39): Product {9BF40A4E-23AE-48be-9974-5A1F261DBEE8} is not already subscribed.
Trace(2013-Oct-08 09:19:39): Product {9BF40A4E-23AE-48be-9974-5A1F261DBEE8} was added to the list.
Trace(2013-Oct-08 09:19:39): Could not read registry entry containing Sophos address - using hardcoded value.
Trace(2013-Oct-08 09:19:39): Could not read registry entry containing Sophos address - using hardcoded value.
Trace(2013-Oct-08 09:19:39): GenerateCustomerID: complete
Trace(2013-Oct-08 09:19:39): IPCBase::IPCBase: Connected to shared memory A32951C539924a12B3C8F2FDA5A268E4
Trace(2013-Oct-08 09:19:39): IPCSender::ProcessSend started
Trace(2013-Oct-08 09:19:39): IPCSender::ProcessSend: No messages in queue, starting to wait
Trace(2013-Oct-08 09:19:39): RMSMessageHandler: ALUpdateStart
Trace(2013-Oct-08 09:19:39): IPCSender::Write: Writing message: <?xml version="1.0" encoding="utf-8" ?><Config type="RMSStartUpdate" />
Trace(2013-Oct-08 09:19:39): IPCSender::ProcessSend: Send message: <?xml version="1.0" encoding="utf-8" ?><Config type="RMSStartUpdate" />
Trace(2013-Oct-08 09:19:39): IPCSender::ProcessSend: No messages in queue, starting to wait
Trace(2013-Oct-08 09:19:39): ALUpdate(AutoUpdate.Started):
Trace(2013-Oct-08 09:19:39): UpdateCoordinator::UpdateNow: Entering
Trace(2013-Oct-08 09:19:39): PopulateCache: Entering
Trace(2013-Oct-08 09:19:39): UpdateCoordinator::UpdateNow: About to Sync list of products
Trace(2013-Oct-08 09:19:39): UpdateLocationFacade::SyncProduct: Last Update Mechanism = CID
Trace(2013-Oct-08 09:19:39): TrySyncProduct<class AutoUpdate::CIDUpdateLocation>, Started:
Trace(2013-Oct-08 09:19:39): TrySyncProduct<class AutoUpdate::CIDUpdateLocation>, creating update location
Trace(2013-Oct-08 09:19:39): Calling package_source_init
Trace(2013-Oct-08 09:19:39): TrySyncProduct, Calling BeginSync
Trace(2013-Oct-08 09:19:39): Logging on network access user
Trace(2013-Oct-08 09:19:39): Attempting to make a connection to remote machine \\SophosServer\SophosUpdate\CIDs\S330\SAVSCFXP\
Trace(2013-Oct-08 09:19:39): Connection to remote machine \\SophosServer\SophosUpdate\CIDs\S330\SAVSCFXP\ successful
Trace(2013-Oct-08 09:19:39): ParseCustomerIDFile: completed: 0
Trace(2013-Oct-08 09:19:39): TrySyncProduct<class AutoUpdate::CIDUpdateLocation>, Calling SyncProduct with {390DCDC2-10A9-4ef3-B8D8-0CA7F0E7EB92}
Trace(2013-Oct-08 09:19:39): CIDUpdateLocation::SyncProduct - Updating Product: RMSNT
Trace(2013-Oct-08 09:19:39): CIDUpdate(SyncProduct.Start): RMSNT, \\SophosServer\SophosUpdate\CIDs\S330\SAVSCFXP\
Trace(2013-Oct-08 09:19:39): Checksum found in master.upd matches cached cidsync.upd : 31251f3f. Skipping download
Trace(2013-Oct-08 09:19:39): CIDUpdate(PrimarySuccess):
Trace(2013-Oct-08 09:19:40): TrySyncProduct<class AutoUpdate::CIDUpdateLocation>, SyncProduct returned - 1
Trace(2013-Oct-08 09:19:40): TrySyncProduct<class AutoUpdate::CIDUpdateLocation>, Ended - 1
Trace(2013-Oct-08 09:19:40): UpdateLocationFacade::SyncProduct: Last Update Mechanism = CID
Trace(2013-Oct-08 09:19:40): CIDUpdateLocation::SyncProduct - Updating Product: SAVXP
Trace(2013-Oct-08 09:19:40): CIDUpdate(SyncProduct.Start): SAVXP, \\SophosServer\SophosUpdate\CIDs\S330\SAVSCFXP\
Trace(2013-Oct-08 09:19:40): Checksum found in master.upd matches cached cidsync.upd : 360bb829. Skipping download
Trace(2013-Oct-08 09:19:40): CIDUpdate(PrimarySuccess):
Trace(2013-Oct-08 09:19:41): UpdateLocationFacade::SyncProduct: Last Update Mechanism = CID
Trace(2013-Oct-08 09:19:41): CIDUpdateLocation::SyncProduct - Updating Product: Sophos AutoUpdate
Trace(2013-Oct-08 09:19:41): CIDUpdate(SyncProduct.Start): Sophos AutoUpdate, \\SophosServer\SophosUpdate\CIDs\S330\SAVSCFXP\
Trace(2013-Oct-08 09:19:41): Checksum found in master.upd matches cached cidsync.upd : 4e8b8359. Skipping download
Trace(2013-Oct-08 09:19:41): CIDUpdate(PrimarySuccess):
Trace(2013-Oct-08 09:19:41): ALUpdate(DownloadEnded):
Trace(2013-Oct-08 09:19:41): UpdateCoordinator::UpdateNow: About to Action list of products
Trace(2013-Oct-08 09:19:41): ALUpdate(Action.Skipped): RMSNT
Trace(2013-Oct-08 09:19:41): ALUpdate(Action.Skipped): SAVXP
Trace(2013-Oct-08 09:19:41): ALUpdate(Action.Skipped): Sophos AutoUpdate
Trace(2013-Oct-08 09:19:42): RMSMessageHandler: ALUpdateEnd
Trace(2013-Oct-08 09:19:42): Sending message: <?xml version="1.0" encoding="utf-8" ?><Config type="RMSEndUpdate" />
Trace(2013-Oct-08 09:19:42): IPCSender::Write: Writing message: <?xml version="1.0" encoding="utf-8" ?><Config type="RMSEndUpdate" />
Trace(2013-Oct-08 09:19:42): IPCSender::ProcessSend: Send message: <?xml version="1.0" encoding="utf-8" ?><Config type="RMSEndUpdate" />
Trace(2013-Oct-08 09:19:42): IPCSender::ProcessSend: No messages in queue, starting to wait
Trace(2013-Oct-08 09:19:43): IPCSender::ProcessSend exiting

Is there something in that log that I don't see which could explain why SEC is not accurate?

On the server side, I don't see anything stock into the Envelopes folder related to that endpoint. In the Router-****.log file, the latest entry regarding that endpoint is the following:

07.10.2013 21:20:08 0A2C I Routing to EM: id=00535DC8, origin=Router$CS1234:720111.Agent, dest=EM, type=EM-GetStatus-Reply
07.10.2013 21:20:08 0A1C I Sent message (id=00535DC8) to EM

On the client side, in the Router-****.log file, I see weird things after 10/7/2013 12:19:41 PM:

07.10.2013 12:19:41 0AA0 I Routing to parent: id=0052DF1D, origin=Router$CS1234:720111.Agent, dest=EM, type=EM-EntityEvent
07.10.2013 12:19:41 0A98 I Sent message (id=0052DF1D) to Router$SophosServer
07.10.2013 13:14:35 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
07.10.2013 14:14:36 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
07.10.2013 15:14:36 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
07.10.2013 15:20:14 0AA0 I Routing to parent: id=0053096E, origin=Router$CS1234:720111.Agent, dest=EM, type=EM-GetStatus-Reply
07.10.2013 15:20:14 0A9C I Sent message (id=0053096E) to Router$SophosServer
07.10.2013 16:14:36 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
07.10.2013 17:14:36 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
07.10.2013 17:22:21 0AA0 I Routing to parent: id=0053260D, origin=Router$CD1234:720111.Agent, dest=EM, type=EM-GetStatus-Reply
07.10.2013 17:22:21 0A94 I Sent message (id=0053260D) to Router$SophosServer
07.10.2013 18:14:36 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
07.10.2013 19:14:36 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
07.10.2013 20:14:36 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
07.10.2013 21:14:36 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
07.10.2013 21:20:08 0AA0 I Routing to parent: id=00535DC8, origin=Router$CS1234:720111.Agent, dest=EM, type=EM-GetStatus-Reply
07.10.2013 21:20:08 0A98 I Sent message (id=00535DC8) to Router$SophosServer
07.10.2013 22:14:37 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
07.10.2013 23:14:37 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 00:14:37 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 00:20:09 0AA0 I Routing to parent: id=005387F9, origin=Router$CS1234:720111.Agent, dest=EM, type=EM-GetStatus-Reply
08.10.2013 00:20:09 0A9C I Sent message (id=005387F9) to Router$SophosServer
08.10.2013 01:14:37 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 02:14:37 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 03:14:37 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 03:20:09 0AA0 I Routing to parent: id=0053B229, origin=Router$CS1234:720111.Agent, dest=EM, type=EM-GetStatus-Reply
08.10.2013 03:20:09 0A94 I Sent message (id=0053B229) to Router$SophosServer
08.10.2013 04:14:37 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 05:14:37 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 06:14:37 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 06:20:09 0AA0 I Routing to parent: id=0053DC59, origin=Router$CS1234:720111.Agent, dest=EM, type=EM-GetStatus-Reply
08.10.2013 06:20:09 0A98 I Sent message (id=0053DC59) to Router$SophosServer
08.10.2013 07:14:37 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 08:14:38 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 09:14:38 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360
08.10.2013 10:14:38 0A54 I RouterSystemCheck::onInfoPortsUsed() - number of user ports 6, max number of user ports 15360

I have been having this problem for the last 2 months. I rebooted the SophosServer and the SQLserver on September 25, which helped for 2 weeks. But now the problem is coming back.

At first, I was restarting the Sophos Message Router service on the endpoints, which seemed to help for a day or 2. I don't think that this workaround is viable considering the amount of endpoints. Can someone help me with that issue?

Thank you for your help!

Cherze

This thread was automatically locked due to age.

Parents

0 QC over 12 years ago

Hello Cherze,
thanks for the additional info. I have still no good idea though about the cause. So this is more thinking out loud. But first some explanation.
Am I misinterpreting the alc.log file?
To be blunt, yes :smileyhappy:. AutoUpdate first goes through the list of products (usually in the order RMS, SAV, SCF and AU) comparing its local cache to the CID (basically it does this by comparing the cached and remote catalogs - master.upd and cidsync.upd, the latter for each of the product folders). If they match there's nothing to download, otherwise the delta is downloaded. Details are in the ALUpdate log, if all goes well ALC shows only the sequence Downloading product ... followed by Product cache update ... successfully finished. When all products have been checked Downloading phase completed is issued. If no new files have been downloaded you see Installation of ... skipped, otherwise Installing product ... and (hopefully) Product has been successfully installed. The cycle is ended with AutoUpdate finished. For failed downloads or installs an alert is sent.
Note that the History in the client details does neither reflect all updates not those where something has been installed. The client doesn't send an unsolicited message on each update (whether without or with install). It does so for failed updates and the next successful update after a failure; otherwise every 48 hours if "always-on". In addition it sends its status periodically.
The Not since timestamp in the Up to date column is not related to the AutoUpdate times reported by the client though. Instead it is derived from the package date (i.e. the time SUM has deployed certain updates to the CID) and version and number of IDEs last reported by the client. The client data is used to identify the package, this is looked up by SEC and the according (adjusted - see next sentence) timestamp is inserted into the Up to date status column. When flagged a client as not up-to-date SEC allows for some latency - by default 60 minutes so the timestamp is adjusted by this amount. Search this forum board for UpToDateLatencyMins to get a little bit more information if you are interested.
As CS1234 is checking for updates it should see a newer package (with the above you can search the logs if it has installed one after 10/7/2013 11:19:41 AM - this time is adjusted. And the local GUI shows the last update under View product information - Anti-virus and HIPS - Software). The RMS log suggests the client does successfully send its status upstream. So you should check the Computer details/Last message time of these allegedly out-of-date computers. It should be fairly recent (for CS1234, if you've found it has performed an actual update shortly after that). If this is not the case then the messages are stuck somewhere. Did you check the Envelopes folder (should have thought of this on my first reply)?
Christian
:44083
Cancel
Vote Up 0 Vote Down

Cancel

Reply

0 QC over 12 years ago

Hello Cherze,
thanks for the additional info. I have still no good idea though about the cause. So this is more thinking out loud. But first some explanation.
Am I misinterpreting the alc.log file?
To be blunt, yes :smileyhappy:. AutoUpdate first goes through the list of products (usually in the order RMS, SAV, SCF and AU) comparing its local cache to the CID (basically it does this by comparing the cached and remote catalogs - master.upd and cidsync.upd, the latter for each of the product folders). If they match there's nothing to download, otherwise the delta is downloaded. Details are in the ALUpdate log, if all goes well ALC shows only the sequence Downloading product ... followed by Product cache update ... successfully finished. When all products have been checked Downloading phase completed is issued. If no new files have been downloaded you see Installation of ... skipped, otherwise Installing product ... and (hopefully) Product has been successfully installed. The cycle is ended with AutoUpdate finished. For failed downloads or installs an alert is sent.
Note that the History in the client details does neither reflect all updates not those where something has been installed. The client doesn't send an unsolicited message on each update (whether without or with install). It does so for failed updates and the next successful update after a failure; otherwise every 48 hours if "always-on". In addition it sends its status periodically.
The Not since timestamp in the Up to date column is not related to the AutoUpdate times reported by the client though. Instead it is derived from the package date (i.e. the time SUM has deployed certain updates to the CID) and version and number of IDEs last reported by the client. The client data is used to identify the package, this is looked up by SEC and the according (adjusted - see next sentence) timestamp is inserted into the Up to date status column. When flagged a client as not up-to-date SEC allows for some latency - by default 60 minutes so the timestamp is adjusted by this amount. Search this forum board for UpToDateLatencyMins to get a little bit more information if you are interested.
As CS1234 is checking for updates it should see a newer package (with the above you can search the logs if it has installed one after 10/7/2013 11:19:41 AM - this time is adjusted. And the local GUI shows the last update under View product information - Anti-virus and HIPS - Software). The RMS log suggests the client does successfully send its status upstream. So you should check the Computer details/Last message time of these allegedly out-of-date computers. It should be fairly recent (for CS1234, if you've found it has performed an actual update shortly after that). If this is not the case then the messages are stuck somewhere. Did you check the Envelopes folder (should have thought of this on my first reply)?
Christian
:44083
Cancel
Vote Up 0 Vote Down

Cancel

Children

No Data