Microsoft App Agent: SQL Backup Fails Due to Expiration Job Overlap

When the backup fails, users are locked out until the backup ends.

Typical errors seen during the backup failure include:

• Unable to write to a file
• ddp_write() failed with error 5057-File handle is stale
• Unable to write data into multiple buffers for save-set ID
• Invalid argument (errno=22)

Logs show the following errors:

2025-03-09T06:33:18.862Z 153005  ddbmsqlsv SYSTEM critical Unable to write to a file.
The error message is: [5057] [50964] [49344] Sun Mar 09 01:33:18 2025
        ddp_write() failed Offset 17626881327104, BytesToWrite 524288, BytesWritten 0 Err: 5057-File handle is stale
2025-03-09T06:33:18.862Z 86699  ddbmsqlsv PowerProtect Data Manager critical Unable to write data into multiple buffers for save-set ID '1741402808': Invalid argument (errno=22)
2025-03-09T06:33:18.916Z 188739  ddbmsqlsv PowerProtect Data Manager warning Backup ID '1741402814' (client 'SqlHost.domain': backup 'MSSQL:DatabaseName~8') is aborted.
2025-03-09T06:33:18.924Z 188739  ddbmsqlsv PowerProtect Data Manager warning Backup ID '1741402817' (client 'SqlHost.domain': backup 'MSSQL:DatabaseName~4') is aborted.
2025-03-09T06:33:18.933Z 188739  ddbmsqlsv PowerProtect Data Manager warning Backup ID '1741402818' (client 'SqlHost.domain': backup 'MSSQL:DatabaseName~12') is aborted.
2025-03-09T06:33:19.324Z 188739  ddbmsqlsv PowerProtect Data Manager warning Backup ID '1741402816' (client 'SqlHost.domain': backup 'MSSQL:DatabaseName~3') is aborted.

Also, the following log entries are seen:

ddbmexptool.messages.log --------------

2025-03-09T06:33:19.475Z 0  ddbmexptool PowerProtect Data Manager notice 1741402814     Deleting '/MtreeName/SqlHost.domain/14/MSSQL2%3aDatabaseName/FULL/index/1741402814.rec' failed [5004] ([12956] [35836] Sun Mar 09 01:33:19 2025
2025-03-09T06:33:19.495Z 0  ddbmexptool PowerProtect Data Manager notice 1741402816     Deleting '/MtreeName/SqlHost.domain/14/MSSQL2%3aDatabaseName/FULL/index/1741402816.rec' failed [5004] ([12956] [35836] Sun Mar 09 01:33:19 2025
2025-03-09T06:33:19.515Z 0  ddbmexptool PowerProtect Data Manager notice 1741402817     Deleting '/MtreeName/SqlHost.domain/14/MSSQL2%3aDatabaseName/FULL/index/1741402817.rec' failed [5004] ([12956] [35836] Sun Mar 09 01:33:19 2025
2025-03-09T06:33:19.540Z 0  ddbmexptool PowerProtect Data Manager notice 1741402818     Deleting '/MtreeName/SqlHost.domain/14/MSSQL2%3aDatabaseName/FULL/index/1741402818.rec' failed [5004] ([12956] [35836] Sun Mar 09 01:33:19 2025
.
 

• Current observations seem to be MSAPPAGENT expiration job (ddbmexptool) running simultaneously as the full backup.
• The full backup takes over 24 hours and during that time the expiration job runs to delete expired save sets past their retention time.
• The timestamp when the expiration job starts to delete save sets, coincides with the timestamp that the backup job fails.
• Another observation is that the MTREE used by MSAPPAGENT backup has replication enabled to two destination targets.
• A test backup with a new MTREE succeeded.
• The new MTREE does not have replication enabled.
• This may require further testing to determine if replication is attributed to the cause.

• Run the MSAPPAGENT backup and avoid overlapping the expiration job (dddbmexptool) with the long-running backup that usually runs over the weekend.
• Alternatively, use a new MTREE for the full backup
• A key factor is to avoid running the expiration job (ddbmexptool) during the long backup.