Server didn't respond in time!

[Bret Miller]

I'm using Avast! SOA 1.3.3.42. I'm getting a lot of these errors in the AvastNet.log and my computers are not showing active in the network view--not even those on the local network. The computer can ping the server on which Avast! is installed. I can even deploy Avast! to a computer successfully. But once deployed, it can't update the subscription so it's always in trial mode. Most computers are Windows 8.1 fully updated. Here are the error messages:

02/25/2015, 17:33:42    avast! NetService identified as srvm-8
02/25/2015, 17:33:42    LoginRequest in Reconnected callback
02/25/2015, 17:34:12    Server didn't respond in time! Trying to wait a little longer.
02/25/2015, 17:34:30    LoginRequest in Reconnected callback
02/25/2015, 17:34:42    Server didn't respond in time! Will Restart NetPump.
02/25/2015, 17:35:42    LoginRequest in Reconnected callback
02/25/2015, 17:36:30    LoginRequest in Reconnected callback
02/25/2015, 17:36:42    Server didn't respond in time! Will Restart NetPump.
02/25/2015, 17:37:42    LoginRequest in Reconnected callback
02/25/2015, 17:38:30    LoginRequest in Reconnected callback
02/25/2015, 17:38:42    Server didn't respond in time! Will Restart NetPump.
02/25/2015, 17:38:42    Server didn't respond in time! Increasing the timeout. (3 minutes)

Any ideas? It's frustrating...

[Bret Miller]

No one?

[Avosec-UK]

Try to ping / nslookup the server address in Avast UI > Settings > Troubleshooting > avast! Administration Console.

Does it resolve the address? Is the address correct?

[Bret Miller]

Yes, I can ping the server address and it is correct. In fact, if I leave the computer on overnight, it will generally eventually connect to the server and get its license. It just shouldn't take 24 hours of doing nothing to do that.

[Avosec-UK]

It shouldn't yes.

Can you check the Avast.Sbc.Service.log located in: C:\ProgramData\AVAST Software\Administration Console\Logs\ on the server where SOA is installed?

Are there any repetitive error messages about some nodes trying to connect?

Kind regards,
Daniel

[Bret Miller]

No. In fact there are no entries at all yesterday from 12:28 to 17:05 and plenty of computers were on and should have been communicating.

There are some strange entries in the log though. Take this section for example:

Code: [Select]

03-25 06:01:38,036 [MP #8] INFO  ServerCore - Incoming login request attempt from computer imisdev.hq.gci.org..
03-25 06:01:38,051 [MP #8] INFO  ServerCore - Logon success for node imisdev.hq.gci.org.
03-25 06:01:38,051 [MP #8] INFO  ServerCore - imisdev.hq.gci.org. successfully logged in, sending login response
03-25 06:01:38,051 [MP #8] INFO  EngineProxyVisitor - Registering engine for node imisdev.hq.gci.org..
03-25 06:01:38,067 [MP #14] INFO  ServerCore - Incoming login request attempt from computer sql1.hq.gci.org..
03-25 06:01:38,082 [MP #13] INFO  ServerCore - Incoming login request attempt from computer mail.hq.gci.org..
03-25 06:01:38,082 [MP #6] INFO  ServerCore - Incoming login request attempt from computer bk1.hq.gci.org..
03-25 06:01:38,098 [MP #18] INFO  ServerCore - Incoming login request attempt from computer t-johnston.hq.gci.org..
03-25 06:01:38,098 [MP #17] INFO  ServerCore - Incoming login request attempt from computer ken-williams.hq.gci.org..
03-25 06:01:38,114 [MP #14] INFO  ServerCore - Logon success for node sql1.hq.gci.org.
03-25 06:01:38,114 [MP #14] INFO  ServerCore - sql1.hq.gci.org. successfully logged in, sending login response
03-25 06:01:38,114 [MP #14] INFO  EngineProxyVisitor - Registering engine for node sql1.hq.gci.org..
03-25 06:01:38,114 [MP #6] INFO  ServerCore - Logon success for node bk1.hq.gci.org.
03-25 06:01:38,114 [MP #6] INFO  ServerCore - bk1.hq.gci.org. successfully logged in, sending login response
03-25 06:01:38,114 [MP #6] INFO  EngineProxyVisitor - Registering engine for node bk1.hq.gci.org..
03-25 06:01:38,114 [MP #13] INFO  ServerCore - Logon success for node mail.hq.gci.org.
03-25 06:01:38,114 [MP #13] INFO  ServerCore - mail.hq.gci.org. successfully logged in, sending login response
03-25 06:01:38,114 [MP #13] INFO  EngineProxyVisitor - Registering engine for node mail.hq.gci.org..
03-25 06:01:38,160 [MP #17] INFO  ServerCore - Logon success for node ken-williams.hq.gci.org.
03-25 06:01:38,160 [MP #17] INFO  ServerCore - ken-williams.hq.gci.org. successfully logged in, sending login response
03-25 06:01:38,160 [MP #17] INFO  EngineProxyVisitor - Registering engine for node ken-williams.hq.gci.org..
03-25 06:01:38,176 [MP #19] INFO  ServerCore - Incoming login request attempt from computer glenn-office.hq.gci.org..
03-25 06:01:38,192 [MP #18] INFO  ServerCore - Logon success for node t-johnston.hq.gci.org.
03-25 06:01:38,192 [MP #18] INFO  ServerCore - t-johnston.hq.gci.org. successfully logged in, sending login response
03-25 06:01:38,192 [MP #18] INFO  EngineProxyVisitor - Registering engine for node t-johnston.hq.gci.org..
03-25 06:01:38,238 [MP #19] INFO  ServerCore - Logon success for node glenn-office.hq.gci.org.
03-25 06:01:38,238 [MP #19] INFO  ServerCore - glenn-office.hq.gci.org. successfully logged in, sending login response
03-25 06:01:38,238 [MP #19] INFO  EngineProxyVisitor - Registering engine for node glenn-office.hq.gci.org..
03-25 06:01:38,270 [MP #0] INFO  ServerCore - Incoming login request attempt from computer auth.hq.gci.org..
03-25 06:01:38,301 [MP #0] INFO  ServerCore - Logon success for node auth.hq.gci.org.
03-25 06:01:38,301 [MP #0] INFO  ServerCore - auth.hq.gci.org. successfully logged in, sending login response
03-25 06:01:38,301 [MP #0] INFO  EngineProxyVisitor - Registering engine for node auth.hq.gci.org..
03-25 06:01:38,472 [MP #13] INFO  ServerCore - Incoming login request attempt from computer gci-dc.hq.gci.org..
03-25 06:01:38,472 [MP #13] INFO  ServerCore - Logon success for node gci-dc.hq.gci.org.
03-25 06:01:38,472 [MP #13] INFO  ServerCore - gci-dc.hq.gci.org. successfully logged in, sending login response
03-25 06:01:38,472 [MP #13] INFO  EngineProxyVisitor - Registering engine for node gci-dc.hq.gci.org..
03-25 06:02:28,612 [MP #12] ERROR ServerForISbcEngineConnectionPoint - Unhandled exception during message invocation!
System.Data.EntityCommandExecutionException: An error occurred while executing the command definition. See the inner exception for details. ---> System.Data.SqlClient.SqlException: Transaction (Process ID 66) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, SqlDataReader ds)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)
   --- End of inner exception stack trace ---
   at System.Data.EntityClient.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommandDefinition.Execute(EntityCommand entityCommand, CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommand.ExecuteScalar[T_Result](Func`2 resultSelector)
   at System.Data.Objects.ObjectContext.ExecuteFunction(String functionName, ObjectParameter[] parameters)
   at Avast.Sbc.Service.Database.EventsDatabase.UpdateProviderStatusBatch(Guid granularityId, Guid computerGUID, String providerName, String rawData)
   at Avast.Sbc.Service.Core.EngineProxyContext.ProviderStatusResponseBatch(Int32 type, Guid computerGUID, String providerName, String data)
   at Avast.Sbc.Service.Core.ServerCore.NotifyProviderStatusHistory2(IOperationContext context, Int32 type, Guid computerGUID, String providerName, String data)
   at Avast.Sbc.Service.Iface.ServerForISbcEngineConnectionPoint.HandleNotifyProviderStatusHistory2(NotifyProviderStatusHistory2Message message)
03-25 06:02:28,628 [MP #14] ERROR ServerForISbcEngineConnectionPoint - Unhandled exception during message invocation!
System.Data.EntityCommandExecutionException: An error occurred while executing the command definition. See the inner exception for details. ---> System.Data.SqlClient.SqlException: Transaction (Process ID 72) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, SqlDataReader ds)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)
   --- End of inner exception stack trace ---
   at System.Data.EntityClient.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommandDefinition.Execute(EntityCommand entityCommand, CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommand.ExecuteScalar[T_Result](Func`2 resultSelector)
   at System.Data.Objects.ObjectContext.ExecuteFunction(String functionName, ObjectParameter[] parameters)
   at Avast.Sbc.Service.Database.EventsDatabase.UpdateProviderStatusBatch(Guid granularityId, Guid computerGUID, String providerName, String rawData)
   at Avast.Sbc.Service.Core.EngineProxyContext.ProviderStatusResponseBatch(Int32 type, Guid computerGUID, String providerName, String data)
   at Avast.Sbc.Service.Core.ServerCore.NotifyProviderStatusHistory2(IOperationContext context, Int32 type, Guid computerGUID, String providerName, String data)
   at Avast.Sbc.Service.Iface.ServerForISbcEngineConnectionPoint.HandleNotifyProviderStatusHistory2(NotifyProviderStatusHistory2Message message)
03-25 06:02:33,417 [MP #6] ERROR ServerForISbcEngineConnectionPoint - Unhandled exception during message invocation!
System.Data.EntityCommandExecutionException: An error occurred while executing the command definition. See the inner exception for details. ---> System.Data.SqlClient.SqlException: Transaction (Process ID 65) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, SqlDataReader ds)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)
   --- End of inner exception stack trace ---
   at System.Data.EntityClient.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommandDefinition.Execute(EntityCommand entityCommand, CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommand.ExecuteScalar[T_Result](Func`2 resultSelector)
   at System.Data.Objects.ObjectContext.ExecuteFunction(String functionName, ObjectParameter[] parameters)
   at Avast.Sbc.Service.Database.EventsDatabase.UpdateProviderStatusBatch(Guid granularityId, Guid computerGUID, String providerName, String rawData)
   at Avast.Sbc.Service.Core.EngineProxyContext.ProviderStatusResponseBatch(Int32 type, Guid computerGUID, String providerName, String data)
   at Avast.Sbc.Service.Core.ServerCore.NotifyProviderStatusHistory2(IOperationContext context, Int32 type, Guid computerGUID, String providerName, String data)
   at Avast.Sbc.Service.Iface.ServerForISbcEngineConnectionPoint.HandleNotifyProviderStatusHistory2(NotifyProviderStatusHistory2Message message)
03-25 06:02:35,929 [MP #5] ERROR ServerForISbcEngineConnectionPoint - Unhandled exception during message invocation!
System.Data.EntityCommandExecutionException: An error occurred while executing the command definition. See the inner exception for details. ---> System.Data.SqlClient.SqlException: Transaction (Process ID 71) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, SqlDataReader ds)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)
   --- End of inner exception stack trace ---
   at System.Data.EntityClient.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommandDefinition.Execute(EntityCommand entityCommand, CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.EntityClient.EntityCommand.ExecuteScalar[T_Result](Func`2 resultSelector)
   at System.Data.Objects.ObjectContext.ExecuteFunction(String functionName, ObjectParameter[] parameters)
   at Avast.Sbc.Service.Database.EventsDatabase.UpdateProviderStatusBatch(Guid granularityId, Guid computerGUID, String providerName, String rawData)
   at Avast.Sbc.Service.Core.EngineProxyContext.ProviderStatusResponseBatch(Int32 type, Guid computerGUID, String providerName, String data)
   at Avast.Sbc.Service.Core.ServerCore.NotifyProviderStatusHistory2(IOperationContext context, Int32 type, Guid computerGUID, String providerName, String data)
   at Avast.Sbc.Service.Iface.ServerForISbcEngineConnectionPoint.HandleNotifyProviderStatusHistory2(NotifyProviderStatusHistory2Message message)


[Avosec-UK]

No. In fact there are no entries at all yesterday from 12:28 to 17:05 and plenty of computers were on and should have been communicating.

There are some strange entries in the log though. Take this section for example:

Code: [Select]

..

Try to restart the avast! Administration Console. The management console service should release the db resources.

[Bret Miller]

Restarting is routine for me when things don't seem to be working right. Restarting preceded the gap in log entries on Tuesday. I'm not sure what to take from that.

I've been wondering if it points to database corruption and if I should consider removing and reinstalling the SOA console. That has drawbacks as there's no easy way to backup and restore settings. But it may be simpler than tracking down and fixing the issue since I don't know when it started.

[Avosec-UK]

If it was a DB corruption, the service wouldn't even start.

The above error means that the management console is trying to update a record in the Database, while a previous attempt is still blocking the record from being updated.

Such locks (theoretically) should not prevent any connections to the console from the clients.

May be debug logs (ADMIN > Settings > Troubleshooting) from the console will reveal more?

[Bret Miller]

After turning on debugging, I restarted the console service. Note that it never ends when I try to stop it, so it's either restart the whole server or kill the process, which I chose to do this time. Then started it from Services again.

Well, I do see a lot more data, though I'm not sure what to do with it. Computers come online, then go off a short time later even though they're still on. Today I was reinstalling another laptop (IT-10446) so I took the opportunity to deploy Avast to it so we'd get a more complete picture. Of course, it still has not gotten its license. And, even though it was on for a little more than an hour yesterday (25 Mar 2015) before I reinstalled it, the console says it hasn't connected since 3 Mar 2015.

Logs if you'd like to see them:

• http://files.gci.org/Avast.Sbc.Service_150326125239.log
• http://files.gci.org/AvastNet.log (from IT-10446)

[Avosec-UK]

I don't think it is a console or a connection problem.

Go to https://www.avast.com/en-eu/resend-license-paid.php type the email of the license and you will get a new one, without the expired product.

Then simply insert it and monitor the clients.

[Bret Miller]

Funny. I already had this discussion with my reseller and they assured me it wasn't the license. Unfortunately that link doesn't work for me--just says that no valid purchases with that email address. So I'll contact my reseller again...

[Bret Miller]

Well, on Friday it looked like fixing the license fixed the problem. Even this morning it was looking better until just recently when I noticed that most computers were shown offline again. The log still shows the service crashing with database deadlocks. Restarting it is obviously only a temporary fix. Didn't have debugging on, so I don't know if the log will be of any help, but here it is:

http://files.gci.org/Avast.Sbc.Service_150330060140.log