PHYlock failures - related to system sitting idle for days?
Posted: Fri Feb 08, 2013 12:11 am
I have been trying to solve this problem for almost a year. Back then, IFW (currently at 2.79) started getting PHYlock failures on my Win7/32 system with 4G of RAM. I can always re-boot and get IFW to work. But this problem makes my unattended scheduled backup ineffective.
I've tried to isolate what causes the failures. First I thought something had been changed by Windows Update. Then I thought it was because I left Firefox open and it used all the RAM.
I have been traveling recently, so I've run a test. Before I left for a week, I restarted the machine. I have enhanced logging (/logl:50) enabled in IFW.
For three weeks in a row, the first IFW scheduled backup runs normally. All the following backups fail with PHYlock errors.
Here is the first log section for the successful run:
[ 2/02/2013 6:28:50 am] /b /un /d:?C: /f:H:\IMAGES\MARS\Auto7\MARS7C.TBI /max:640MiB /vb /mf /logl:50
[ 2/02/2013 6:28:51 am] Image for Windows 2.79 (GUI)
[ 2/02/2013 6:28:51 am] Starting ...
imagew.exe /b /un /d:w0@0x89 /f:"H:\IMAGES\MARS\Auto7\MARS7C" /max:640MiB /vb
[ 2/02/2013 6:28:52 am] PHYLock is waiting for drive writing to stop ...
[ 2/02/2013 6:28:52 am] DLD
[ 2/02/2013 6:28:52 am] FVMS
[ 2/02/2013 6:28:52 am] BSFN
[ 2/02/2013 6:28:52 am] COV
[ 2/02/2013 6:28:52 am] GNR
[ 2/02/2013 6:28:55 am] DVTS NR:8422
[ 2/02/2013 6:28:55 am] SII VF
[ 2/02/2013 6:28:55 am] SSR
[ 2/02/2013 6:28:55 am] WLS
[ 2/02/2013 6:29:14 am] SH
[ 2/02/2013 6:29:14 am] ULV
[ 2/02/2013 6:29:14 am] CSF
[ 2/02/2013 6:29:15 am] PHYLock using drive C:
[ 2/02/2013 6:29:15 am] EF
[ 2/02/2013 6:29:15 am] FFB
[ 2/02/2013 6:29:15 am] FMLCN
[ 2/02/2013 6:29:15 am] L SVCN:0 EC:1
[ 2/02/2013 6:29:15 am] CH
[ 2/02/2013 6:29:15 am] SHTPD
[ 2/02/2013 6:29:15 am] SWITCH
[ 2/02/2013 6:29:15 am] CU
[ 2/02/2013 6:29:15 am] CUC
[ 2/02/2013 6:29:15 am] EXIT
[ 2/02/2013 6:29:15 am] PHYLock Started
[ 2/02/2013 6:29:15 am] PHYLock Using Disk
[ 2/02/2013 6:29:15 am] PHYLock version 10
[ 2/02/2013 6:29:17 am] Backup: Drive 0 (C:) C-MARS-W7 Partition (89) 99998 MiB HPFS/NTFS
[ 2/02/2013 6:29:17 am] To: H:\IMAGES\MARS\Auto7\MARS7C.TBI
[ 2/02/2013 6:51:36 am] INFO: Total Sectors:204796620 Total Allocated:143399832
[ 2/02/2013 6:51:36 am] INFO: 130560184 Sector(s) backed up
[ 2/02/2013 6:51:36 am] Validating: C-MARS-W7 Partition (89) 99998 MiB HPFS/NTFS
[ 2/02/2013 6:51:36 am] From: H:\IMAGES\MARS\Auto7\MARS7C.TBI
[ 2/02/2013 7:09:20 am] Operation Completed with Error Code 0
[ 2/02/2013 7:09:20 am] Stop
--------------------------------------------------------------------------
The script runs every day, and if the image is more than 3 days old, it runs IFW. So the next time IFW runs is on 2/6, it fails:
[ 2/06/2013 6:30:26 am] /b /un /d:?C: /f:H:\IMAGES\MARS\Auto7\MARS7C.TBI /max:640MiB /vb /mf /logl:50
[ 2/06/2013 6:30:26 am] Image for Windows 2.79 (GUI)
[ 2/06/2013 6:30:26 am] Starting ...
imagew.exe /b /un /d:w0@0x89 /f:"H:\IMAGES\MARS\Auto7\MARS7C" /max:640MiB /vb
[ 2/06/2013 6:30:27 am] PHYLock is waiting for drive writing to stop ...
[ 2/06/2013 6:30:27 am] DLD
[ 2/06/2013 6:30:27 am] FVMS
[ 2/06/2013 6:30:27 am] BSFN
[ 2/06/2013 6:30:27 am] COV
[ 2/06/2013 6:30:27 am] GNR
[ 2/06/2013 6:30:27 am] DVTS NR:9965
[ 2/06/2013 6:30:31 am] EXIT
[ 2/06/2013 6:30:31 am] PHYLock Failed to Start
[ 2/06/2013 6:30:31 am] Unable to start PHYLock for drive C:
You may need to reduce the cache size.
[ 2/06/2013 6:30:31 am] Deleting incomplete or failed backup.
[ 2/06/2013 6:30:31 am] Operation Completed with Error Code 68
[ 2/06/2013 6:30:31 am] Stop
--------------------------------------------------------------------------
This pattern repeats every day:
[ 2/07/2013 6:30:18 am] /b /un /d:?C: /f:H:\IMAGES\MARS\Auto7\MARS7C.TBI /max:640MiB /vb /mf /logl:50
[ 2/07/2013 6:30:19 am] Image for Windows 2.79 (GUI)
[ 2/07/2013 6:30:19 am] Starting ...
imagew.exe /b /un /d:w0@0x89 /f:"H:\IMAGES\MARS\Auto7\MARS7C" /max:640MiB /vb
[ 2/07/2013 6:30:21 am] PHYLock is waiting for drive writing to stop ...
[ 2/07/2013 6:30:21 am] DLD
[ 2/07/2013 6:30:21 am] FVMS
[ 2/07/2013 6:30:21 am] BSFN
[ 2/07/2013 6:30:21 am] COV
[ 2/07/2013 6:30:21 am] GNR
[ 2/07/2013 6:30:23 am] DVTS NR:10003
[ 2/07/2013 6:30:26 am] EXIT
[ 2/07/2013 6:30:26 am] PHYLock Failed to Start
[ 2/07/2013 6:30:26 am] Unable to start PHYLock for drive C:
You may need to reduce the cache size.
[ 2/07/2013 6:30:26 am] Deleting incomplete or failed backup.
[ 2/07/2013 6:30:26 am] Operation Completed with Error Code 68
[ 2/07/2013 6:30:26 am] Stop
It continues to fail with similar results until I reboot the machine. Then it runs one more time.
This system has used this same backup script literally for years (since IFW 1.x days), and has never had issues until recently.
I have confirmed that nothing else is running on the system at the time the backup script runs - just the empty Windows desktop.
I have captured the tasklist each on each run, right before IFW starts. There is no difference in running tasks between the successful run and the failure.
So my hypotheses are:
A) something happens when the system is idle, hibernates, and wakes up that causes PHYlock failures.
B) A successful run with PHYlock does something to the system that prevents PHYlock from working again.
Neither of these seem very likely, because they would have developed "spontaneously" from a system that formerly worked.
The difference seems to be after the "DVTS NR" phase. When PHYlock works, there are a number of other phases following "DVTS NR". When it fails, the next debug output is "EXIT", then "PHYLock Failed to Start".
Here are some examples of DVTS and the number following it:
[11/21/2012 6:20:48 am] DVTS NR:5237 - Success
[11/29/2012 6:15:49 am] DVTS NR:5005 - Failed
[12/03/2012 6:18:08 am] DVTS NR:6030 - Failed
[12/04/2012 6:19:37 am] DVTS NR:6569 - Failed
[12/04/2012 9:25:49 am] DVTS NR:6646 - Success
[12/08/2012 6:20:51 am] DVTS NR:5878 - Success
[12/12/2012 6:22:44 am] DVTS NR:4881 - Failed
[12/13/2012 6:21:42 am] DVTS NR:4252 - Failed
[12/14/2012 6:21:06 am] DVTS NR:4303 - Failed
[12/15/2012 6:21:06 am] DVTS NR:4676 - Failed
[12/15/2012 11:55:55 am] DVTS NR:4412 - Success
[12/19/2012 6:25:44 am] DVTS NR:5103 - Success
[12/23/2012 6:27:58 am] DVTS NR:5901 - Failed
[12/24/2012 6:24:27 am] DVTS NR:7088 - Success
[12/27/2012 6:48:53 am] DVTS NR:8133 - Failed
[12/27/2012 9:05:04 am] DVTS NR:8106 - Success
[12/31/2012 6:18:50 am] DVTS NR:8657 - Success
[ 1/04/2013 6:24:59 am] DVTS NR:6320 - Success
[ 1/08/2013 6:23:51 am] DVTS NR:7844 - Failed
[ 1/09/2013 6:29:08 am] DVTS NR:5838 - Failed
[ 1/09/2013 6:06:41 pm] DVTS NR:5995 - Success
[ 1/13/2013 6:29:40 am] DVTS NR:6215 - Failed
[ 1/17/2013 6:30:14 am] DVTS NR:7446 - Failed
[ 1/18/2013 6:29:07 am] DVTS NR:7528 - Failed
[ 1/19/2013 6:31:50 am] DVTS NR:7467 - Failed
[ 1/19/2013 11:00:43 am] DVTS NR:7093 - Success
[ 1/23/2013 6:31:29 am] DVTS NR:8174 - Failed
[ 1/24/2013 6:29:43 am] DVTS NR:7712 - Failed
[ 1/25/2013 6:29:57 am] DVTS NR:7769 - Failed
[ 1/26/2013 6:29:37 am] DVTS NR:7704 - Failed
[ 1/26/2013 8:55:50 pm] DVTS NR:8267 - Failed
[ 1/26/2013 9:02:10 pm] DVTS NR:8262 - Success
[ 1/30/2013 6:31:27 am] DVTS NR:7990 - Failed
[ 1/31/2013 6:29:24 am] DVTS NR:8499 - Failed
[ 2/01/2013 6:30:23 am] DVTS NR:8497 - Failed
[ 2/02/2013 6:28:55 am] DVTS NR:8422 - Success
[ 2/06/2013 6:30:27 am] DVTS NR:9965 - Failed
[ 2/07/2013 6:30:23 am] DVTS NR:10003 - Failed
Looking at all the recent data, I do not see a conclusive relationship between the number following DVTS NR: and the outcome.
I've tried to isolate what causes the failures. First I thought something had been changed by Windows Update. Then I thought it was because I left Firefox open and it used all the RAM.
I have been traveling recently, so I've run a test. Before I left for a week, I restarted the machine. I have enhanced logging (/logl:50) enabled in IFW.
For three weeks in a row, the first IFW scheduled backup runs normally. All the following backups fail with PHYlock errors.
Here is the first log section for the successful run:
[ 2/02/2013 6:28:50 am] /b /un /d:?C: /f:H:\IMAGES\MARS\Auto7\MARS7C.TBI /max:640MiB /vb /mf /logl:50
[ 2/02/2013 6:28:51 am] Image for Windows 2.79 (GUI)
[ 2/02/2013 6:28:51 am] Starting ...
imagew.exe /b /un /d:w0@0x89 /f:"H:\IMAGES\MARS\Auto7\MARS7C" /max:640MiB /vb
[ 2/02/2013 6:28:52 am] PHYLock is waiting for drive writing to stop ...
[ 2/02/2013 6:28:52 am] DLD
[ 2/02/2013 6:28:52 am] FVMS
[ 2/02/2013 6:28:52 am] BSFN
[ 2/02/2013 6:28:52 am] COV
[ 2/02/2013 6:28:52 am] GNR
[ 2/02/2013 6:28:55 am] DVTS NR:8422
[ 2/02/2013 6:28:55 am] SII VF
[ 2/02/2013 6:28:55 am] SSR
[ 2/02/2013 6:28:55 am] WLS
[ 2/02/2013 6:29:14 am] SH
[ 2/02/2013 6:29:14 am] ULV
[ 2/02/2013 6:29:14 am] CSF
[ 2/02/2013 6:29:15 am] PHYLock using drive C:
[ 2/02/2013 6:29:15 am] EF
[ 2/02/2013 6:29:15 am] FFB
[ 2/02/2013 6:29:15 am] FMLCN
[ 2/02/2013 6:29:15 am] L SVCN:0 EC:1
[ 2/02/2013 6:29:15 am] CH
[ 2/02/2013 6:29:15 am] SHTPD
[ 2/02/2013 6:29:15 am] SWITCH
[ 2/02/2013 6:29:15 am] CU
[ 2/02/2013 6:29:15 am] CUC
[ 2/02/2013 6:29:15 am] EXIT
[ 2/02/2013 6:29:15 am] PHYLock Started
[ 2/02/2013 6:29:15 am] PHYLock Using Disk
[ 2/02/2013 6:29:15 am] PHYLock version 10
[ 2/02/2013 6:29:17 am] Backup: Drive 0 (C:) C-MARS-W7 Partition (89) 99998 MiB HPFS/NTFS
[ 2/02/2013 6:29:17 am] To: H:\IMAGES\MARS\Auto7\MARS7C.TBI
[ 2/02/2013 6:51:36 am] INFO: Total Sectors:204796620 Total Allocated:143399832
[ 2/02/2013 6:51:36 am] INFO: 130560184 Sector(s) backed up
[ 2/02/2013 6:51:36 am] Validating: C-MARS-W7 Partition (89) 99998 MiB HPFS/NTFS
[ 2/02/2013 6:51:36 am] From: H:\IMAGES\MARS\Auto7\MARS7C.TBI
[ 2/02/2013 7:09:20 am] Operation Completed with Error Code 0
[ 2/02/2013 7:09:20 am] Stop
--------------------------------------------------------------------------
The script runs every day, and if the image is more than 3 days old, it runs IFW. So the next time IFW runs is on 2/6, it fails:
[ 2/06/2013 6:30:26 am] /b /un /d:?C: /f:H:\IMAGES\MARS\Auto7\MARS7C.TBI /max:640MiB /vb /mf /logl:50
[ 2/06/2013 6:30:26 am] Image for Windows 2.79 (GUI)
[ 2/06/2013 6:30:26 am] Starting ...
imagew.exe /b /un /d:w0@0x89 /f:"H:\IMAGES\MARS\Auto7\MARS7C" /max:640MiB /vb
[ 2/06/2013 6:30:27 am] PHYLock is waiting for drive writing to stop ...
[ 2/06/2013 6:30:27 am] DLD
[ 2/06/2013 6:30:27 am] FVMS
[ 2/06/2013 6:30:27 am] BSFN
[ 2/06/2013 6:30:27 am] COV
[ 2/06/2013 6:30:27 am] GNR
[ 2/06/2013 6:30:27 am] DVTS NR:9965
[ 2/06/2013 6:30:31 am] EXIT
[ 2/06/2013 6:30:31 am] PHYLock Failed to Start
[ 2/06/2013 6:30:31 am] Unable to start PHYLock for drive C:
You may need to reduce the cache size.
[ 2/06/2013 6:30:31 am] Deleting incomplete or failed backup.
[ 2/06/2013 6:30:31 am] Operation Completed with Error Code 68
[ 2/06/2013 6:30:31 am] Stop
--------------------------------------------------------------------------
This pattern repeats every day:
[ 2/07/2013 6:30:18 am] /b /un /d:?C: /f:H:\IMAGES\MARS\Auto7\MARS7C.TBI /max:640MiB /vb /mf /logl:50
[ 2/07/2013 6:30:19 am] Image for Windows 2.79 (GUI)
[ 2/07/2013 6:30:19 am] Starting ...
imagew.exe /b /un /d:w0@0x89 /f:"H:\IMAGES\MARS\Auto7\MARS7C" /max:640MiB /vb
[ 2/07/2013 6:30:21 am] PHYLock is waiting for drive writing to stop ...
[ 2/07/2013 6:30:21 am] DLD
[ 2/07/2013 6:30:21 am] FVMS
[ 2/07/2013 6:30:21 am] BSFN
[ 2/07/2013 6:30:21 am] COV
[ 2/07/2013 6:30:21 am] GNR
[ 2/07/2013 6:30:23 am] DVTS NR:10003
[ 2/07/2013 6:30:26 am] EXIT
[ 2/07/2013 6:30:26 am] PHYLock Failed to Start
[ 2/07/2013 6:30:26 am] Unable to start PHYLock for drive C:
You may need to reduce the cache size.
[ 2/07/2013 6:30:26 am] Deleting incomplete or failed backup.
[ 2/07/2013 6:30:26 am] Operation Completed with Error Code 68
[ 2/07/2013 6:30:26 am] Stop
It continues to fail with similar results until I reboot the machine. Then it runs one more time.
This system has used this same backup script literally for years (since IFW 1.x days), and has never had issues until recently.
I have confirmed that nothing else is running on the system at the time the backup script runs - just the empty Windows desktop.
I have captured the tasklist each on each run, right before IFW starts. There is no difference in running tasks between the successful run and the failure.
So my hypotheses are:
A) something happens when the system is idle, hibernates, and wakes up that causes PHYlock failures.
B) A successful run with PHYlock does something to the system that prevents PHYlock from working again.
Neither of these seem very likely, because they would have developed "spontaneously" from a system that formerly worked.
The difference seems to be after the "DVTS NR" phase. When PHYlock works, there are a number of other phases following "DVTS NR". When it fails, the next debug output is "EXIT", then "PHYLock Failed to Start".
Here are some examples of DVTS and the number following it:
[11/21/2012 6:20:48 am] DVTS NR:5237 - Success
[11/29/2012 6:15:49 am] DVTS NR:5005 - Failed
[12/03/2012 6:18:08 am] DVTS NR:6030 - Failed
[12/04/2012 6:19:37 am] DVTS NR:6569 - Failed
[12/04/2012 9:25:49 am] DVTS NR:6646 - Success
[12/08/2012 6:20:51 am] DVTS NR:5878 - Success
[12/12/2012 6:22:44 am] DVTS NR:4881 - Failed
[12/13/2012 6:21:42 am] DVTS NR:4252 - Failed
[12/14/2012 6:21:06 am] DVTS NR:4303 - Failed
[12/15/2012 6:21:06 am] DVTS NR:4676 - Failed
[12/15/2012 11:55:55 am] DVTS NR:4412 - Success
[12/19/2012 6:25:44 am] DVTS NR:5103 - Success
[12/23/2012 6:27:58 am] DVTS NR:5901 - Failed
[12/24/2012 6:24:27 am] DVTS NR:7088 - Success
[12/27/2012 6:48:53 am] DVTS NR:8133 - Failed
[12/27/2012 9:05:04 am] DVTS NR:8106 - Success
[12/31/2012 6:18:50 am] DVTS NR:8657 - Success
[ 1/04/2013 6:24:59 am] DVTS NR:6320 - Success
[ 1/08/2013 6:23:51 am] DVTS NR:7844 - Failed
[ 1/09/2013 6:29:08 am] DVTS NR:5838 - Failed
[ 1/09/2013 6:06:41 pm] DVTS NR:5995 - Success
[ 1/13/2013 6:29:40 am] DVTS NR:6215 - Failed
[ 1/17/2013 6:30:14 am] DVTS NR:7446 - Failed
[ 1/18/2013 6:29:07 am] DVTS NR:7528 - Failed
[ 1/19/2013 6:31:50 am] DVTS NR:7467 - Failed
[ 1/19/2013 11:00:43 am] DVTS NR:7093 - Success
[ 1/23/2013 6:31:29 am] DVTS NR:8174 - Failed
[ 1/24/2013 6:29:43 am] DVTS NR:7712 - Failed
[ 1/25/2013 6:29:57 am] DVTS NR:7769 - Failed
[ 1/26/2013 6:29:37 am] DVTS NR:7704 - Failed
[ 1/26/2013 8:55:50 pm] DVTS NR:8267 - Failed
[ 1/26/2013 9:02:10 pm] DVTS NR:8262 - Success
[ 1/30/2013 6:31:27 am] DVTS NR:7990 - Failed
[ 1/31/2013 6:29:24 am] DVTS NR:8499 - Failed
[ 2/01/2013 6:30:23 am] DVTS NR:8497 - Failed
[ 2/02/2013 6:28:55 am] DVTS NR:8422 - Success
[ 2/06/2013 6:30:27 am] DVTS NR:9965 - Failed
[ 2/07/2013 6:30:23 am] DVTS NR:10003 - Failed
Looking at all the recent data, I do not see a conclusive relationship between the number following DVTS NR: and the outcome.