"Timed Out - Start" error of SQL DB backups

Do you see anything in the client logs ?

Hello Subash,

"Timed Out - Start"means : MCS has sent the workorder to Avagent on client,  but client couldn't start processing the workorder due to x number of reasons. Once, we reach the default limit of backup scheduler end, MCS aborts these workorders and thus the status "Timed Out - Start".

It is important to review Avagent.log on client's VAR directory to review any anomalies.

Furthermore, it would be good if you can attach the same to this thread.

Hi Gautam and Pankaj,

The Database environment is SQL AlwaysOn. We have configured AlwaysOn SQL DB backup and physical node SQL DB backup. I don’t see any logs particularly belongs to that physical node SQL DB backup (Timed Out – Start) which ran at 22:00 Hrs neither from “:\*****\avs\var\clientlogs” nor from “:\******\avs\var” except below piece of logs from “:\*******\avs\var\avagent.txt”. As you can see that, at 20:03 and at 21:01, every hour at non scheduled time window, Client keep on checking request from Avamar Server every after 3500 Approx. seconds till scheduled backup time (22:00). At and After 22:00 Hrs, it is keep on checking every after 240 seconds.

Logs for Physical Node SQL DB Backup at 22:00 Hrs :-

2016-08-15 20:03:28 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-15 20:03:30 avagent Info <5264>: Workorder received: sleep
2016-08-15 20:03:30 avagent Info <5996>: Sleeping 3490 seconds
2016-08-15 21:01:40 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-15 21:01:40 avagent Info <5264>: Workorder received: sleep
2016-08-15 21:01:40 avagent Info <5996>: Sleeping 3708 seconds
2016-08-15 22:03:28 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-15 22:03:28 avagent Info <5264>: Workorder received: sleep
2016-08-15 22:03:28 avagent Info <5996>: Sleeping 240 seconds
2016-08-15 22:07:28 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-15 22:07:28 avagent Info <5264>: Workorder received: sleep
2016-08-15 22:07:28 avagent Info <5996>: Sleeping 240 seconds

As per my observation, when backup was running I didn’t see any avtar process(es) on client. 28002 port working fine. I canceled the scheduled backup (status : Waiting Queue) and immediately initiated on-demand backup that one running fine. Almost at the same time.

And for SQL AlwaysOn Backup (Status :- Waiting Queue / Timed Out – Start), I don’t see any specific logs in Var folder and in avagent.txt except below one and the logs of manual initiated backup which is running fine.

Avagent logs for SQL AlwaysOn listener backup :-

016-08-15 23:03:50 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-15 23:03:50 avagent Info <5264>: Workorder received: sleep
2016-08-15 23:03:50 avagent Info <5996>: Sleeping 3543 seconds
2016-08-16 00:02:53 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-16 00:02:53 avagent Info <5264>: Workorder received: sleep
2016-08-16 00:02:53 avagent Info <5996>: Sleeping 240 seconds
2016-08-16 00:06:53 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-16 00:06:53 avagent Info <5264>: Workorder received: sleep
2016-08-16 00:06:53 avagent Info <5996>: Sleeping 240 seconds
2016-08-16 00:10:53 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-16 00:10:53 avagent Info <5264>: Workorder received: sleep
2016-08-16 00:10:53 avagent Info <5996>: Sleeping 240 seconds
==============
Mannual initiated backup logs :-

2016-08-16 01:26:54 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-16 01:26:54 avagent Info <5264>: Workorder received: sleep
2016-08-16 01:26:54 avagent Info <5996>: Sleeping 240 seconds
2016-08-16 01:30:54 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-16 01:30:54 avagent Info <5264>: Workorder received: sleep
2016-08-16 01:30:54 avagent Info <5996>: Sleeping 240 seconds
2016-08-16 01:33:11 avagent Info <6685>: Browse process 108684 (:\********\avs\bin\avsql) started

2016-08-16 01:33:12 avagent Info <10684>: Setting ctl message version to 3 (from 1)
2016-08-16 01:33:12 avagent Info <16136>: Setting ctl max message size to 268435456
2016-08-16 01:33:44 avagent Info <5962>: Wake up message received

-Deb

Deb,

For : And for SQL AlwaysOn Backup (Status :- Waiting Queue / Timed Out – Start), I don’t see any specific logs in Var folder and in avagent.txt except below one and the logs of manual initiated backup which is running fine.

Can you attach the avagent.log from the AG's Listener's VAR also known as Shared VAR directory?

Also, share the backup window time(Start / End)

Hi Pankaj,

Due to some restriction, I won’t be able to upload avagent.txt log but in log, I am getting only below message.

2016-08-16 00:10:53 avagent Info <5964>: Requesting work from Avamar_Master_Server
2016-08-16 00:10:53 avagent Info <5264>: Workorder received: sleep
2016-08-16 00:10:53 avagent Info <5996>: Sleeping 240 seconds

VMs backup are running fine.

Subhash,

At this time, i would recommend you to open a support ticket. Please proceed with the same.

Thanks,
Pankaj Pande