Failed to lock the file
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


- Log in to post comments

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
- Log in to post comments

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?
- Log in to post comments

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

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.confSamba 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.confSamba 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.confSamba 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] #
- Log in to post comments

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.confSamba 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.confSamba 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.confSamba 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] #
- Log in to post comments

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!
- Log in to post comments

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.
- Log in to post comments

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.
- Log in to post comments

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
- Log in to post comments

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.
- Log in to post comments

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
- Log in to post comments

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
- Log in to post comments

Well, didn't help me at all. I have one more experiment before backing off this version of ATI.
- Log in to post comments