Skip to main content

Failed to lock the file

Thread needs solution

Acronis True Image 2021 build 39216.  Windows 11 Pro, build 22000.282

Scheduled backup.  NAS as backup destination.  Since couple days ago, I'm getting "Failed to loc the file" error.  Originally, I though it was the connection/credential problem with the NAS.  But if I clicked "Backup Now" without doing anything else, the backup will succeed.  So it doesn't seem to be a connection/credential problem.  How shall I troubleshoot this?  Thank you!

 

11/3/2021 12:09:10 AM: -05:00 17420 I00000000: -----
11/3/2021 12:09:10 AM: -05:00 17420 I00000000: ATI Demon started. Version: 25.8.1.39216.
11/3/2021 12:09:10 AM: -05:00 17420 I00640000: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
11/3/2021 12:09:10 AM: -05:00 17420 I00640002: Operation P50 started by schedule.
11/3/2021 12:09:10 AM: -05:00 17420 I00640000: Backup reserve copy attributes: format tib; need_reserve_backup_copy false;
11/3/2021 12:09:10 AM: -05:00 17420 I013C0000: Operation: Backup
11/3/2021 12:09:10 AM: -05:00 17420 I0064000B: Priority changed to Low.
11/3/2021 12:10:20 AM: -05:00 17420 I00010400: Child process has exited with code '0'.
11/3/2021 12:10:20 AM: -05:00 17420 I00640086: Execution of user command succeeded: C:/Windows/QNAP_On.cmd
11/3/2021 12:10:20 AM: -05:00 17420 E00040017: Error 0x40017: Failed to lock the file.
| trace level: error
| line: 0xaa33a143c434a604
| file: c:\jenkins_agent\workspace\ati-main-win-ati\62\home\backup_worker\impl\backup_worker.cpp:182
| function: `anonymous-namespace'::ReturnCodeToError
| line: 0xaa33a143c434a604, c:\jenkins_agent\workspace\ati-main-win-ati\62\home\backup_worker\impl\backup_worker.cpp:182, `anonymous-namespace'::ReturnCodeToError
| $module: ti_demon_vs_39216
|
| error 0x40017: Failed to lock the file.
| line: 0xc8d8731ce106f9e6
| file: c:\jenkins_agent\workspace\ati-main-win-ati\62\archive\ver3\adapter\error.cpp:88
| function: `anonymous-namespace'::ConvertArchive3Error
| line: 0xc8d8731ce106f9e6, c:\jenkins_agent\workspace\ati-main-win-ati\62\archive\ver3\adapter\error.cpp:88, `anonymous-namespace'::ConvertArchive3Error
| $module: archive3_adapter_vs_39216
11/3/2021 12:10:20 AM: -05:00 17420 E013C0005: Error 0x13c0005: Operation has completed with errors.
| trace level: error
| line: 0x9f2c53c72e8bcedb
| file: c:\jenkins_agent\workspace\ati-main-win-ati\62\products\imager\demon\main.cpp:741
| function: main
| line: 0x9f2c53c72e8bcedb, c:\jenkins_agent\workspace\ati-main-win-ati\62\products\imager\demon\main.cpp:741, main
| $module: ti_demon_vs_39216

Start: 11/3/2021 12:09:10 AM
Stop: 11/3/2021 12:10:20 AM
Total Time: 00:01:10

0 Users found this helpful

Michael, from your information, you are making an Entire PC type backup of disks & partitions therefore you need to look at the Backup Worker log for more details on what file cannot be locked for this task?

You need to be using the new log viewer tool per the link below. 
MVP Assistant - a new tool, including new Log Viewer (Latest version 1.1.4.0, 9/27/2021)

If you have Disks & Partitions backups created on ATI 2020 or later using .tibx files, then look in the Backup Worker logs.

If you have Files & Folders backups using .tib files (or Disk backups from earlier versions using .tib files) or using Cloning then look in the Demon logs.

Other logs are shown by the MVP Assistant under the 'Active Logs' heading of the Log Viewer page of the Assistant.

The log files should be zipped to preserve their original file names if sharing in the forums and would need to be less than 3MB in size, otherwise you would need to share the zip file via a Cloud share service such as OneDrive, Dropbox etc.

Steve, Thank you for your help!

It looks like TI was having problem opening the tibx file on NAS.  Here is some information regarding the NAS:

My NAS is normally in sleep mode.  I use a script (Wake On LAN) to wake it up as a "Pre Command" of the backup job.  Then I use another script to put it back in sleep after the job.  This has been working fine until couple days ago.

My backup job was scheduled at midnight.  In the morning, when I saw the "Failed to lock file" error, the NAS is turned on (obviously the script woke it up).  I clicked the "Backup Now" button and the job completed successfully.

I was thinking maybe something went wrong in the wakeup process.  For testing purpose, I put the NAS back in sleep mode again.  Then I click the "Backup Now" button.  The NAS was waken up.  But the job failed with "Failed to lock file".  While the NAS is still on, I tried to run the job manually.  Now it failed every time with "failed to lock file".

From Windows, I can open the UNC and see the tibx file.  How shall I determine the root cause?  Thanks!

11/3/2021 12:10:20:279 AM -05:00 17420 I00000000: Pid: 8408 >>> --id=10001 --action=browse --agent="ATI 25.8.1.39216 Win" --archive="smb://QNAP/Backup/P50.tibx" --ar-loc-username="admin" --ar-loc-password=*
11/3/2021 12:10:20:369 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=inf; message=ar#1: opening archive path="\\?\UNC\QNAP\Backup\\P50.tibx" in readonly mode;
11/3/2021 12:10:20:388 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=inf; message=ar#1: ci page found at 652964765696;
11/3/2021 12:10:20:389 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=inf; message=ar#1: opened archive path="\\?\UNC\QNAP\Backup\\P50.tibx" mode=readonly reopen=1:0 commit=30/30 size=0/652964769792 uuid=1b6a054ec88779615f7cdb51f9a82e70 type=disk features=d--;
11/3/2021 12:10:20:389 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=inf; message=ar#1: slices=4 user=785112MB data=621644MB meta=201MB unused=869MB/0.14% deallocated=0MB/0.00%;
11/3/2021 12:10:20:451 AM -05:00 17420 I00000000: Pid: 8408 >>>
11/3/2021 12:10:20:463 AM -05:00 17420 I00000000: Pid: 8408 >>>
11/3/2021 12:10:20:463 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=inf; message=ar#1: archive closing;
11/3/2021 12:10:20:465 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=inf; message=io#1: time=0d00:00:00 total req=0 (rd=0 wr=0 sync=0), pgreq=0 (rd=0 wr=0) sync=0.0 ms;
11/3/2021 12:10:20:465 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=inf; message=io#1: pg cache hit=2 ra_hit=0 ra_pages=0 ra=0.00%;
11/3/2021 12:10:20:465 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=inf; message=ar#1: archive close (commit=30/30, file_size=652964769792, uuid=1b6a054ec88779615f7cdb51f9a82e70, user read=0MB write=0MB) rc=0 (Success);
11/3/2021 12:10:20:467 AM -05:00 14200 I00000000: Pid: 8408 type=retcode; value=0; id=10001;
11/3/2021 12:10:20:468 AM -05:00 17420 I00000000: Pid: 8408 >>> --id=1 --action=backup --action=cleanup --action=metainfo --disk-backup --agent="ATI 25.8.1.39216 Win" --archive="smb://QNAP/Backup/P50.tibx" --ar-loc-username="admin" --ar-loc-password=* --source="\\local" --exclude-wildcard="hiberfil.sys" --exclude-wildcard="pagefile.sys" --exclude-wildcard="$Recycle.Bin" --exclude-wildcard="swapfile.sys" --exclude-wildcard="System Volume Information" --exclude-wildcard="*.tib" --exclude-wildcard="*.tibx" --exclude-wildcard="*.tib.metadata" --exclude-wildcard="*.~" --exclude-wildcard="*.tmp" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Mozilla\\Firefox\\Profiles\\*\\cache2" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Mozilla\\Firefox\\Profiles\\*\\OfflineCache" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Opera Software\\Opera Stable\\Cache" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Opera Software\\Opera Stable\\Media Cache" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Google\\Chrome\\User Data\\Default\\Cache" --exclude-wildcard="C:\\WINDOWS\\CSC" --exclude-wildcard="E:\\" --exclude-wildcard="R:\\" --exclude-wildcard="D:\\VirtualMachines\\Lab\\" --machine-name="P50" --machine-id="4D9D4F15-B79C-45D1-ACE1-83B697959A57" --resource-id="BD0C378D-3CC7-4415-9A98-C01AE58AD620" --resource-type="entire-pc" --vss-mode="vss" --backup-scheme="inc" --keep-versions=5
11/3/2021 12:10:20:474 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=inf; message=ar#1: opening archive path="\\?\UNC\QNAP\Backup\\P50.tibx" in rewrite mode (create);
11/3/2021 12:10:20:478 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=err; message=io: failed to open '\\?\UNC\QNAP\Backup\P50.tibx' (win_err=-32);
11/3/2021 12:10:20:478 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=inf; message=pcs_sync_open(\\?\UNC\QNAP\Backup\P50.tibx) failed: 32 (pcs_err=22);
11/3/2021 12:10:20:482 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=err; message=io#1: failed to open "\\?\UNC\QNAP\Backup\\P50.tibx" (pcs_err=-22);
11/3/2021 12:10:20:482 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=err; message=ar#1: failed to open archive path="\\?\UNC\QNAP\Backup\\P50.tibx" mode=rewrite uuid=00000000000000000000000000000000, err=-5015 (Object is locked);
11/3/2021 12:10:20:482 AM -05:00 14200 I00000000: Pid: 8408 type=log; level=err; message=unable to open archive file (err -5015);
11/3/2021 12:10:20:484 AM -05:00 14200 I00000000: Pid: 8408 type=retcode; value=5015; id=1;
11/3/2021 12:10:20:485 AM -05:00 17420 I00000000: Pid: 8408 >>> exit

Michael, just looking at some of the messages in the log snippet above, the line:

failed to open archive path="\\?\UNC\QNAP\Backup\\P50.tibx" mode=rewrite uuid=00000000000000000000000000000000, err=-5015 (Object is locked);

would suggest that a process on the NAS is holding a lock against the .tibx file.

Is there any scheduled scan tasks performed on the NAS such as a virus scan etc?

Perhaps a restart of the NAS might clear the lock status?

Steve, I rebooted the NAS.  I'll report back tomorrow as the daily backup was scheduled for midnight.  Thank you again for your help!

Steve,

The problem happened again in scheduled daily backup.  The backup job tried six times then gave up.  Here's the backup worker log for the first try.

11/4/2021 12:01:18:635 AM -05:00 22056 I00000000: Pid: 19048 >>> --id=10001 --action=browse --agent="ATI 25.8.1.39216 Win" --archive="smb://QNAP/Backup/P50.tibx" --ar-loc-username="admin" --ar-loc-password=*
11/4/2021 12:01:18:866 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: opening archive path="\\?\UNC\QNAP\Backup\\P50.tibx" in readonly mode;
11/4/2021 12:01:48:898 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: ci page found at 683331592192;
11/4/2021 12:01:48:899 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: opened archive path="\\?\UNC\QNAP\Backup\\P50.tibx" mode=readonly reopen=1:0 commit=33/33 size=0/683331596288 uuid=1b6a054ec88779615f7cdb51f9a82e70 type=disk features=d--;
11/4/2021 12:01:48:899 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: slices=6 user=822415MB data=650434MB meta=242MB unused=999MB/0.15% deallocated=0MB/0.00%;
11/4/2021 12:01:49:142 AM -05:00 22056 I00000000: Pid: 19048 >>>
11/4/2021 12:01:49:152 AM -05:00 22056 I00000000: Pid: 19048 >>>
11/4/2021 12:01:49:152 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: archive closing;
11/4/2021 12:01:49:153 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=io#1: time=0d00:00:30 total req=0 (rd=0 wr=0 sync=0), pgreq=0 (rd=0 wr=0) sync=0.0 ms;
11/4/2021 12:01:49:153 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=io#1: pg cache hit=2 ra_hit=0 ra_pages=0 ra=0.00%;
11/4/2021 12:01:49:153 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: archive close (commit=33/33, file_size=683331596288, uuid=1b6a054ec88779615f7cdb51f9a82e70, user read=0MB write=0MB) rc=0 (Success);
11/4/2021 12:01:49:155 AM -05:00 2564 I00000000: Pid: 19048 type=retcode; value=0; id=10001;
11/4/2021 12:01:49:156 AM -05:00 22056 I00000000: Pid: 19048 >>> --id=1 --action=backup --action=cleanup --action=metainfo --disk-backup --agent="ATI 25.8.1.39216 Win" --archive="smb://QNAP/Backup/P50.tibx" --ar-loc-username="admin" --ar-loc-password=* --source="\\local" --exclude-wildcard="hiberfil.sys" --exclude-wildcard="pagefile.sys" --exclude-wildcard="$Recycle.Bin" --exclude-wildcard="swapfile.sys" --exclude-wildcard="System Volume Information" --exclude-wildcard="*.tib" --exclude-wildcard="*.tibx" --exclude-wildcard="*.tib.metadata" --exclude-wildcard="*.~" --exclude-wildcard="*.tmp" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Mozilla\\Firefox\\Profiles\\*\\cache2" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Mozilla\\Firefox\\Profiles\\*\\OfflineCache" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Opera Software\\Opera Stable\\Cache" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Opera Software\\Opera Stable\\Media Cache" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Google\\Chrome\\User Data\\Default\\Cache" --exclude-wildcard="C:\\WINDOWS\\CSC" --exclude-wildcard="E:\\" --exclude-wildcard="R:\\" --exclude-wildcard="D:\\VirtualMachines\\Lab\\" --machine-name="P50" --machine-id="4D9D4F15-B79C-45D1-ACE1-83B697959A57" --resource-id="BD0C378D-3CC7-4415-9A98-C01AE58AD620" --resource-type="entire-pc" --vss-mode="vss" --backup-scheme="inc" --keep-versions=7
11/4/2021 12:01:49:161 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: opening archive path="\\?\UNC\QNAP\Backup\\P50.tibx" in rewrite mode (create);
11/4/2021 12:01:49:166 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=err; message=io: failed to open '\\?\UNC\QNAP\Backup\P50.tibx' (win_err=-32);
11/4/2021 12:01:49:166 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=pcs_sync_open(\\?\UNC\QNAP\Backup\P50.tibx) failed: 32 (pcs_err=22);
11/4/2021 12:01:49:170 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=err; message=io#1: failed to open "\\?\UNC\QNAP\Backup\\P50.tibx" (pcs_err=-22);
11/4/2021 12:01:49:170 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=err; message=ar#1: failed to open archive path="\\?\UNC\QNAP\Backup\\P50.tibx" mode=rewrite uuid=00000000000000000000000000000000, err=-5015 (Object is locked);
11/4/2021 12:01:49:170 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=err; message=unable to open archive file (err -5015);
11/4/2021 12:01:49:172 AM -05:00 2564 I00000000: Pid: 19048 type=retcode; value=5015; id=1;
11/4/2021 12:01:49:174 AM -05:00 22056 I00000000: Pid: 19048 >>> exit

Here's the NAS command line output.  The timestamps match with each backup attempt (6 times in total).  So it looks like the backup job locked up the file? 

[/mnt/HDA_ROOT] # /usr/local/samba/bin/smbstatus -v
using configfile = /etc/config/smb.conf

Samba version 4.4.16
PID     Username     Group        Machine                                   Protocol Version  Encryption           Signing
----------------------------------------------------------------------------------------------------------------------------------------
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)

Service pid     Username        Adderess        Machine Connected at    Encryption      Signing
QNAP need start--------------------------------------
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:06:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:09:22 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:07:52 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:04:50 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:03:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:01:50 AM 2021 CDT -       -
QNAP need end--------------------------------------

Locked files:
Pid          Uid        DenyMode   Access      R/W        Oplock           SharePath   Name   Time
--------------------------------------------------------------------------------------------------
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:09:21 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:01:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:03:19 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:04:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:06:20 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:07:51 2021

[/mnt/HDA_ROOT] #

 

The weird thing is: even with the following output, I was able to do a manual backup without any problem (by clicking the "Backup Now" button).  Here's the NAS command line output while I'm doing the manual backup.  Timestamp 06:51:09 is the manual backup.

[/mnt/HDA_ROOT] # /usr/local/samba/bin/smbstatus -v
using configfile = /etc/config/smb.conf

Samba version 4.4.16
PID     Username     Group        Machine                                   Protocol Version  Encryption           Signing
----------------------------------------------------------------------------------------------------------------------------------------
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)

Service pid     Username        Adderess        Machine Connected at    Encryption      Signing
QNAP need start--------------------------------------
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:06:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:09:22 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:07:52 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:04:50 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 06:51:09 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:03:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:01:50 AM 2021 CDT -       -
QNAP need end--------------------------------------

Locked files:
Pid          Uid        DenyMode   Access      R/W        Oplock           SharePath   Name   Time
--------------------------------------------------------------------------------------------------
26403        0          DENY_NONE  0x12019f    RDWR       LEASE(RWH)       /share/CACHEDEV1_DATA/Backup   P50.tibx   Thu Nov  4 06:51:09 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:09:21 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:01:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:03:19 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:04:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:06:20 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:07:51 2021

[/mnt/HDA_ROOT] #

After the backup job completed successfully, here's the NAS output:

[/mnt/HDA_ROOT] # /usr/local/samba/bin/smbstatus -v
using configfile = /etc/config/smb.conf

Samba version 4.4.16
PID     Username     Group        Machine                                   Protocol Version  Encryption           Signing
----------------------------------------------------------------------------------------------------------------------------------------
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)

Service pid     Username        Adderess        Machine Connected at    Encryption      Signing
QNAP need start--------------------------------------
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:06:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 06:57:26 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:09:22 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:07:52 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:04:50 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:03:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:01:50 AM 2021 CDT -       -
QNAP need end--------------------------------------

Locked files:
Pid          Uid        DenyMode   Access      R/W        Oplock           SharePath   Name   Time
--------------------------------------------------------------------------------------------------
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:09:21 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:01:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:03:19 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:04:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:06:20 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:07:51 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 06:57:26 2021

[/mnt/HDA_ROOT] #

Steve,

The problem happened again in scheduled daily backup.  The backup job tried six times then gave up.  Here's the backup worker log for the first try.

11/4/2021 12:01:18:635 AM -05:00 22056 I00000000: Pid: 19048 >>> --id=10001 --action=browse --agent="ATI 25.8.1.39216 Win" --archive="smb://QNAP/Backup/P50.tibx" --ar-loc-username="admin" --ar-loc-password=*
11/4/2021 12:01:18:866 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: opening archive path="\\?\UNC\QNAP\Backup\\P50.tibx" in readonly mode;
11/4/2021 12:01:48:898 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: ci page found at 683331592192;
11/4/2021 12:01:48:899 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: opened archive path="\\?\UNC\QNAP\Backup\\P50.tibx" mode=readonly reopen=1:0 commit=33/33 size=0/683331596288 uuid=1b6a054ec88779615f7cdb51f9a82e70 type=disk features=d--;
11/4/2021 12:01:48:899 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: slices=6 user=822415MB data=650434MB meta=242MB unused=999MB/0.15% deallocated=0MB/0.00%;
11/4/2021 12:01:49:142 AM -05:00 22056 I00000000: Pid: 19048 >>>
11/4/2021 12:01:49:152 AM -05:00 22056 I00000000: Pid: 19048 >>>
11/4/2021 12:01:49:152 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: archive closing;
11/4/2021 12:01:49:153 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=io#1: time=0d00:00:30 total req=0 (rd=0 wr=0 sync=0), pgreq=0 (rd=0 wr=0) sync=0.0 ms;
11/4/2021 12:01:49:153 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=io#1: pg cache hit=2 ra_hit=0 ra_pages=0 ra=0.00%;
11/4/2021 12:01:49:153 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: archive close (commit=33/33, file_size=683331596288, uuid=1b6a054ec88779615f7cdb51f9a82e70, user read=0MB write=0MB) rc=0 (Success);
11/4/2021 12:01:49:155 AM -05:00 2564 I00000000: Pid: 19048 type=retcode; value=0; id=10001;
11/4/2021 12:01:49:156 AM -05:00 22056 I00000000: Pid: 19048 >>> --id=1 --action=backup --action=cleanup --action=metainfo --disk-backup --agent="ATI 25.8.1.39216 Win" --archive="smb://QNAP/Backup/P50.tibx" --ar-loc-username="admin" --ar-loc-password=* --source="\\local" --exclude-wildcard="hiberfil.sys" --exclude-wildcard="pagefile.sys" --exclude-wildcard="$Recycle.Bin" --exclude-wildcard="swapfile.sys" --exclude-wildcard="System Volume Information" --exclude-wildcard="*.tib" --exclude-wildcard="*.tibx" --exclude-wildcard="*.tib.metadata" --exclude-wildcard="*.~" --exclude-wildcard="*.tmp" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Mozilla\\Firefox\\Profiles\\*\\cache2" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Mozilla\\Firefox\\Profiles\\*\\OfflineCache" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Opera Software\\Opera Stable\\Cache" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Opera Software\\Opera Stable\\Media Cache" --exclude-wildcard="D:\\Users\\User\\AppData\\Local\\Google\\Chrome\\User Data\\Default\\Cache" --exclude-wildcard="C:\\WINDOWS\\CSC" --exclude-wildcard="E:\\" --exclude-wildcard="R:\\" --exclude-wildcard="D:\\VirtualMachines\\Lab\\" --machine-name="P50" --machine-id="4D9D4F15-B79C-45D1-ACE1-83B697959A57" --resource-id="BD0C378D-3CC7-4415-9A98-C01AE58AD620" --resource-type="entire-pc" --vss-mode="vss" --backup-scheme="inc" --keep-versions=7
11/4/2021 12:01:49:161 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=ar#1: opening archive path="\\?\UNC\QNAP\Backup\\P50.tibx" in rewrite mode (create);
11/4/2021 12:01:49:166 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=err; message=io: failed to open '\\?\UNC\QNAP\Backup\P50.tibx' (win_err=-32);
11/4/2021 12:01:49:166 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=inf; message=pcs_sync_open(\\?\UNC\QNAP\Backup\P50.tibx) failed: 32 (pcs_err=22);
11/4/2021 12:01:49:170 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=err; message=io#1: failed to open "\\?\UNC\QNAP\Backup\\P50.tibx" (pcs_err=-22);
11/4/2021 12:01:49:170 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=err; message=ar#1: failed to open archive path="\\?\UNC\QNAP\Backup\\P50.tibx" mode=rewrite uuid=00000000000000000000000000000000, err=-5015 (Object is locked);
11/4/2021 12:01:49:170 AM -05:00 2564 I00000000: Pid: 19048 type=log; level=err; message=unable to open archive file (err -5015);
11/4/2021 12:01:49:172 AM -05:00 2564 I00000000: Pid: 19048 type=retcode; value=5015; id=1;
11/4/2021 12:01:49:174 AM -05:00 22056 I00000000: Pid: 19048 >>> exit

Here's the NAS command line output.  The timestamps match with each backup attempt (6 times in total).  So it looks like the backup job locked up the file? 

[/mnt/HDA_ROOT] # /usr/local/samba/bin/smbstatus -v
using configfile = /etc/config/smb.conf

Samba version 4.4.16
PID     Username     Group        Machine                                   Protocol Version  Encryption           Signing
----------------------------------------------------------------------------------------------------------------------------------------
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)

Service pid     Username        Adderess        Machine Connected at    Encryption      Signing
QNAP need start--------------------------------------
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:06:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:09:22 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:07:52 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:04:50 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:03:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:01:50 AM 2021 CDT -       -
QNAP need end--------------------------------------

Locked files:
Pid          Uid        DenyMode   Access      R/W        Oplock           SharePath   Name   Time
--------------------------------------------------------------------------------------------------
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:09:21 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:01:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:03:19 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:04:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:06:20 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:07:51 2021

[/mnt/HDA_ROOT] #

 

The weird thing is: even with the following output, I was able to do a manual backup without any problem (by clicking the "Backup Now" button).  Here's the NAS command line output while I'm doing the manual backup.  Timestamp 06:51:09 is the manual backup.

[/mnt/HDA_ROOT] # /usr/local/samba/bin/smbstatus -v
using configfile = /etc/config/smb.conf

Samba version 4.4.16
PID     Username     Group        Machine                                   Protocol Version  Encryption           Signing
----------------------------------------------------------------------------------------------------------------------------------------
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)

Service pid     Username        Adderess        Machine Connected at    Encryption      Signing
QNAP need start--------------------------------------
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:06:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:09:22 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:07:52 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:04:50 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 06:51:09 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:03:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:01:50 AM 2021 CDT -       -
QNAP need end--------------------------------------

Locked files:
Pid          Uid        DenyMode   Access      R/W        Oplock           SharePath   Name   Time
--------------------------------------------------------------------------------------------------
26403        0          DENY_NONE  0x12019f    RDWR       LEASE(RWH)       /share/CACHEDEV1_DATA/Backup   P50.tibx   Thu Nov  4 06:51:09 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:09:21 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:01:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:03:19 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:04:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:06:20 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:07:51 2021

[/mnt/HDA_ROOT] #

After the backup job completed successfully, here's the NAS output:

[/mnt/HDA_ROOT] # /usr/local/samba/bin/smbstatus -v
using configfile = /etc/config/smb.conf

Samba version 4.4.16
PID     Username     Group        Machine                                   Protocol Version  Encryption           Signing
----------------------------------------------------------------------------------------------------------------------------------------
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)
26403   admin         administrators  p50          (192.168.2.76) SMB3_11           -                    partial(AES-128-CMAC)

Service pid     Username        Adderess        Machine Connected at    Encryption      Signing
QNAP need start--------------------------------------
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:06:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 06:57:26 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:09:22 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:07:52 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:04:50 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:03:20 AM 2021 CDT -       -
Backup  26403   admin   192.168.2.76    p50     Thu Nov  4 12:01:50 AM 2021 CDT -       -
QNAP need end--------------------------------------

Locked files:
Pid          Uid        DenyMode   Access      R/W        Oplock           SharePath   Name   Time
--------------------------------------------------------------------------------------------------
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:09:21 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:01:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:03:19 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:04:49 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:06:20 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 00:07:51 2021
26403        0          DENY_NONE  0x100081    RDONLY     NONE             /share/CACHEDEV1_DATA/Backup   .   Thu Nov  4 06:57:26 2021

[/mnt/HDA_ROOT] #

I reviewed the NAS config.  Here's the configuration of the shared folder "Backup".

I unchecked both "Lock File (Oplocks)" and "Enable Windows Previous Versions", and rebooted the NAS.  I'll report back tomorrow.  Thanks!

Uncheck the "Lock File (Oplocks)" seems to solve the problem.  But I'm curious why True Image would have problem with that.  True Image is the only user who would access the shared folder on the NAS.

 

Michael, Acronis can only work with the environment that it finds itself using - I haven't seen this type of issue with my Synology NAS and haven't seen any matching option in the settings.

Steve Smith wrote:

Michael, Acronis can only work with the environment that it finds itself using - I haven't seen this type of issue with my Synology NAS and haven't seen any matching option in the settings.

Same here with my aging Synology NAS.

Ian 

I have been struggling with a problem on my Synology NAS for over a year.

In my case it occurs on weekly full disk backups. I am running ATI 2019 and I believe the problem started with that version. When I recently updated my wife's PC from ATI 2018 to ATI 2019 the problem started with her similar backup tasks.

In my case the Demon log shows it writing the new .tib file, but then immediately says it cannot access the .tib file. I have checked the logs on the NAS and it shows the SMB connection to the NAS is fine, but there is no log entry for the creation of the file.

It has always worked to start the backup manually. All failures have happened when starting by schedule. It does not fail every time, but often enough. The failures have occurred form two different PCs and they also occurred with my older Synology DS213j and my new DS220+. They have occurred with Synology DSM version 6 and 7.

I just checked both NAS boxes and found the setting you refer to. On Synology DSM, under Control Panel->File Services->SMB, click on Advanced Settings to find Enable Opportunistic Locking. I found it set on both my devices so I've now cleared it. Steve, Ian, how is that option set on your NAS?

I was about to revert to ATI 2018 to see if that would help but now there is new life in my struggle for a solution. Now to see what happens over the next week or so.

 

 

Bruno, have checked the settings on my DS215J and my settings are as shown below:

I have included the second image showing WS-Discovery being enabled as this was a change I made several years ago based on the following webpage article (that I think Bob recommended at that time).

Webpage: How to kill off SMB1, NetBIOS, WINS and *still* have Windows' Network Neighbourhood better than ever

I have "Enable opportunistic locking" selected in my settings (took a while to find the setting - do not look at the all that often). Unlike Steve I do not have "Enable SMB2 lease" selected. Not sure that this helps ...

Ian

Well, didn't help me at all. I have one more experiment before backing off this version of ATI.