Hi,

Kevin Harvie helped me with this error a couple weeks ago. He advised me that it was a bug when I use ImageManager and segmented backups. As a workaround, he advised me to set the ImageManager policy to only do a collapse once a day rather than every hour, so there would always be a file to collapse. I set it to run at midnight and every 1440 minutes thereafter.

Now I am getting the same error when collapsing weeklys.

Kevin is out of the office. Support asked me to post the issue in the forum.

Mark Berry 

Application Event Log
---------------------
Source:  StorageCraft Image Man
Event ID:  1121
Type:  Error
Description:  Directory - H:\ShadowProtect\MyServer File name - F_VOL-b001-i118-cd-cw.spi Unexpected end of the image file  


Here is the ImageManager.log detail from the second error:

16-Aug-2008 10:53:47 Enforce weekly cleanup policy
16-Aug-2008 10:53:47 Collapse files, type = 2 F_VOL-b001-i062-cd.spi F_VOL-b001-i063-cd.spi F_VOL-b001-i074-cd.spi F_VOL-b001-i085-cd.spi F_VOL-b001-i096-cd.spi F_VOL-b001-i107-cd.spi F_VOL-b001-i118-cd.spi
16-Aug-2008 10:57:55 sbset 404 Cannot open file H:\ShadowProtect\MyServer\F_VOL-b001-i063-cd.spi.sp1 (-2 The system cannot find the file specified.)
16-Aug-2008 10:57:55 sbcrypt 500 Unexpected end of the image file
16-Aug-2008 10:57:55 (loader) 504 Final error (-2 The system cannot find the file specified.)

The log is accurate:  there is no "F_VOL-b001-i063-cd.spi.sp1" file.  Only these files exist:

F_VOL-b001-i063.spi
F_VOL-b001-i063.spi.sp1
F_VOL-b001-i063-cd.spi

I also don't understand why the weekly collapses are occurring at 10:57am when I set the policy for collapses to occur at midnight. But that is a separate issue.

The problem is happening because ImageManager is not dealing with split image files correctly.  It only occurs when there is a single backup at collapse time and ImageManager renames or copies the file to have a -cd.spi extension.  Only the first split file is renamed instead of all split files.  This is resolved in the upcoming release of 3.3 but you can correct this particular issue by renaming "F_VOL-b001-i063.spi.sp1" to "F_VOL-b001-i063-cd.spi.sp1".

Thanks Doug. I've done the rename. We'll see what happens. I wonder if my backup chain is, or will be, intact.

Now, why was the weekly done at 10:53am when I configured ImageManager to do collapses at midnight? I have lots of things scheduled on this server, including defragmentation of the USB drive that ShadowProtect and ImageManager are writing to. How do I configure when ImageManager does ALL of its collapse operations?

Thanks,

Mark
 

If you restart the ImageManager service it should retry the weekly collapse that failed.  The chain should still be intact.

The weekly and monthly collapses occur at the same time of day that the oldest full backup in the directory was created.  Currently there is no UI to change this time, you can only change when the daily collapse occurs.

Doug, 

Thanks for your reply.

Well I restarted the service. It appears that it started a collapse immediately. Apparently this is another situation where ImageManager is operating outside the configured settings (collapse at midnight). I'm all for having a manual "Collapse Now" button, but I do not like to see server processes running unexpectedly, that is, when they are not configured to run. Just because I reboot the server or restart the service does not mean that I want to collapse files.

While I was checking the ImageManager.log to see what happened after restarting the service, I saw the following sequence of messages:

18-Aug-2008 00:00:28 Collapse files, type = 1
C_VOL-b001-i130.spi
18-Aug-2008 00:00:28 Copy H:\ShadowProtect\MyServer\C_VOL-b001-i130.spi to H:\ShadowProtect\MyServer\C_VOL-b001-i130-cd.spi
18-Aug-2008 00:00:58 Collapse files, type = 1
F_VOL-b001-i130.spi
18-Aug-2008 00:00:58 Copy H:\ShadowProtect\MyServer\F_VOL-b001-i130.spi to H:\ShadowProtect\MyServer\F_VOL-b001-i130-cd.spi
18-Aug-2008 00:02:40 Collapse files, type = 1
D_VOL-b001-i130.spi
18-Aug-2008 00:02:40 Copy H:\ShadowProtect\MyServer\D_VOL-b001-i130.spi to H:\ShadowProtect\MyServer\D_VOL-b001-i130-cd.spi
18-Aug-2008 00:02:45 Enforce Policy
18-Aug-2008 00:02:45 Enforce daily cleanup policy
18-Aug-2008 00:02:45 daily wait = 23:57:43
18-Aug-2008 00:02:51 InsertFile exception: F_VOL-b001-i130-cd.spi ERROR [23000] [Microsoft][ODBC Microsoft Access Driver] The changes you requested to the table were not successful because they would create duplicate values in the index, primary key, or relationship.  Change the data in the field or fields that contain duplicate data, remove the index, or redefine the index to permit duplicate entries and try again.
22-Aug-2008 12:25:01 Database rename from F_VOL-b001-i063.spi.sp1 to F_VOL-b001-i063-cd.spi.sp1
22-Aug-2008 12:25:01 F_VOL-b001-i063.spi.sp1 renamed to F_VOL-b001-i063-cd.spi.sp1
22-Aug-2008 14:39:55 Processing stop message
22-Aug-2008 14:39:56 Error adding F_VOL-b001-i130-cd.spi
22-Aug-2008 14:39:57 Watch thread finished

I guess ImageManager stopped working four days ago, on Monday August 18. Sure enough, there is a Warning error in the Application event log at 12:02:51AM on 8/18. I monitor event log Errors every day. Seems like if an application is shutting itself down due to a database error, that could be considered worthy of an Error event, not just a Warning.

Further down in ImageManager.log, I see:

22-Aug-2008 14:47:26 Enforce Policy
22-Aug-2008 14:47:26 weekly check prior to Aug 09
22-Aug-2008 14:47:26 weekly check prior to Aug 16
22-Aug-2008 14:47:26 Collapse files, type = 2
F_VOL-b001-i062-cd.spi
F_VOL-b001-i063-cd.spi
F_VOL-b001-i074-cd.spi
F_VOL-b001-i085-cd.spi
F_VOL-b001-i096-cd.spi
F_VOL-b001-i107-cd.spi
F_VOL-b001-i118-cd.spi
22-Aug-2008 14:52:06 sbset 404 Cannot open file H:\ShadowProtect\MyServer\F_VOL-b001-i063-cd.spi.sp1 (-2 The system cannot find the file specified.)
22-Aug-2008 14:52:06 sbcrypt 500 Unexpected end of the image file
22-Aug-2008 14:52:06 (loader) 504 Final error (-2 The system cannot find the file specified.)

This one at least generated an Error in the Application event log.

Do I need to just give up on continuous incrementals and ImageManager until 3.3?

Mark  

From what we have seen database errors are rare but can be resolved by using the original ImageManager.mdb file.  Stop the StorageCraft ImageManager service and replace the .mdb file in the install directory with the file extracted from the attached .zip file.  Restart ImageManager and the database will sync with the directory contents.

ImageManager is typically used for chains that do not have the split file option set.  If you need split files, I would suggest not using continuous incrementals until 3.3 is available.

Regards,

Mark