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.
