Can't image 2003 SBS

ximerian · July 16, 2012, 12:52pm

I’m having trouble imaging Windows 2003 Small Business Servers. The only other image one I’ve tried so far though is WindowsXP.

It’ll do the file backups fine, but when it tries to do the image backup I get.
07/16/12 01:34:27: ERROR: Pipe to client unexpectedly closed
07/16/12 01:34:28: ERROR: Backup not complete because of connection problems

I’m running the latest client, and the server was built from source on Gentoo.

I’m not sure where to even go from here, can anyone lend some assistance?

Thanks

uroni · July 16, 2012, 3:25pm

Are you running a x86 or x64 version on Windows?

More information may also be found in C:\Program files\UrBackup\debug.log on the client.

Does the image backup start and that error occur in the middle of the backup or does is occur right at the begining?

ximerian · July 16, 2012, 6:35pm

x86 - It happens at the very beginning. The client says ‘Waiting for server…’ and then the above error is generated.

Here is the debug.log

[quote=""]ERROR: Error opening device file ()
07/16/12 01:39:14: ERROR: Opening Shadow drive filesystem failed. Stopping.
07/16/12 01:39:41: ERROR: Pipe broken -2
[/quote]

I just realized on the XP box that it does image successfully the volume shadow copy service is actually stopped, and on the server it is running. I’ll try stopping the service and image it tonight after hours.

Thanks!

EDIT: Doing it on my test server now. The client sits there saying ‘Waiting for server…’ guess that wasn’t it.

uroni · July 16, 2012, 7:07pm

Yes looks like shadow copying fails or it fails to open the shadow copy after it was created. If you change the “warn” to “debug” in C:\Program files\UrBackup\args.txt it will print out more information including the paths it tries to access.

ximerian · July 16, 2012, 7:40pm

The new log, I don’t have a clue…is this helpful at all?

It just keeps repeating over and over until eventually it stops trying.

[quote=""]07/16/12 15:34:21: Loaded -fileserv- plugin
07/16/12 15:34:21: Loaded -fsimageplugin- plugin
07/16/12 15:34:21: Loaded -cryptoplugin- plugin
07/16/12 15:34:21: Starting as client…
07/16/12 15:34:21: Started UrBackup…
07/16/12 15:34:21: urbackupserver: Server started up sucessfully!
07/16/12 15:34:21: Backup privileges set successfully
07/16/12 15:34:21: Info: retval 0
07/16/12 15:34:21: Info: retval 0
07/16/12 15:34:21: Info: Window size=524288
07/16/12 15:34:21: Binding udp socket…
07/16/12 15:34:21: done.
07/16/12 15:34:21: Disabling new behavior…
07/16/12 15:34:21: Servername: -srk01-
07/16/12 15:34:21: Server started up sucessfully
07/16/12 15:34:21: UDP Thread startet
07/16/12 15:34:22: Looking for old Sessions… 0 sessions
07/16/12 15:34:25: urbackupserver: New Connection incomming 2977296 s: 436
07/16/12 15:34:25: urbackupserver: No available slots… starting new Worker
07/16/12 15:34:25: Incoming data for client…
07/16/12 15:34:25: ClientService cmd: #Iashsniskeyghirxsrvdnoflwchnykv#1CHANNEL capa=0
07/16/12 15:34:25: New channel: Number of Channels: 1
07/16/12 15:34:26: urbackupserver: New Connection incomming 2978906 s: 464
07/16/12 15:34:26: Incoming data for client…
07/16/12 15:34:26: ClientService cmd: #Iashsniskeyghirxsrvdnoflwchnykv#PING RUNNING -0-#token=akojffsxpywxiiqgdkehasooqqxgpi
07/16/12 15:34:26: Incoming data for client…
07/16/12 15:34:26: rc=0 hasError=true state=0
07/16/12 15:34:26: urbackupserver: Removing user2978921
07/16/12 15:34:29: urbackupserver: New Connection incomming 2981265 s: 464
07/16/12 15:34:29: Incoming data for client…
07/16/12 15:34:29: ClientService cmd: STATUS#pw=YEtuod0Uxfr5pHs1kdfCWeu1J6jp9w
07/16/12 15:34:29: Incoming data for client…
07/16/12 15:34:29: rc=0 hasError=true state=0
07/16/12 15:34:29: urbackupserver: Removing user2981281
07/16/12 15:34:29: urbackupserver: New Connection incomming 2981281 s: 464
07/16/12 15:34:29: Incoming data for client…
07/16/12 15:34:29: ClientService cmd: GET INCRINTERVALL#pw=YEtuod0Uxfr5pHs1kdfCWeu1J6jp9w
07/16/12 15:34:29: Incoming data for client…
07/16/12 15:34:29: rc=0 hasError=true state=0
07/16/12 15:34:29: urbackupserver: Removing user2981296[/quote]

uroni · July 16, 2012, 7:44pm

Not really. Interesting would be the debug messages surrounding the error message you posted before that.

ximerian · July 16, 2012, 7:51pm

I cleared the log file after switching it from warn to debug, that was everything from the top of the file to the point when it started repeating the same message.

ximerian · July 16, 2012, 11:36pm

Does the image backup communicate to the server in a different manner than the file one? I’m wondering if the ‘Waiting for server…’ from the client system tray icon would be at all helpful?

ximerian · July 17, 2012, 12:39am

Reinstalled the client, put the ‘debug’ back in the args nad got this. Looks like it might have what you were expecting to see before.

[quote=""]Incoming data for client…
07/16/12 20:36:34: ClientService cmd: #Iashsniskeyghirxsrvdnoflwchnykv#PING RUNNING -0-#token=akojffsxpywxiiqgdkehasooqqxgpi
07/16/12 20:36:34: Incoming data for client…
07/16/12 20:36:34: rc=0 hasError=true state=0
07/16/12 20:36:34: urbackupserver: Removing user1420593
07/16/12 20:36:35: urbackupserver: New Connection incomming 1421343 s: 1188
07/16/12 20:36:35: Incoming data for client…
07/16/12 20:36:35: ClientService cmd: STATUS#pw=FLoaxlCsKZXrsGbnLVy4r4MB2PhuZ9
07/16/12 20:36:35: Incoming data for client…
07/16/12 20:36:35: rc=0 hasError=true state=0
07/16/12 20:36:35: urbackupserver: Removing user1421359
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: ERROR: Pipe broken -2
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Sending full image done
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Deleting shadowcopy for path “\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy5” -2
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: Deleting Shadowcopy for dir “C:”
07/16/12 20:36:41: Incoming data for client…
07/16/12 20:36:41: rc=0 hasError=true state=4
07/16/12 20:36:41: urbackupserver: Removing user1427750
07/16/12 20:36:44: urbackupserver: New Connection incomming 1430593 s: 368
07/16/12 20:36:44: Incoming data for client…
07/16/12 20:36:44: ClientService cmd: #Iashsniskeyghirxsrvdnoflwchnykv#PING RUNNING -0-#token=akojffsxpywxiiqgdkehasooqqxgpi
07/16/12 20:36:44: Incoming data for client…
07/16/12 20:36:44: rc=0 hasError=true state=0
07/16/12 20:36:44: urbackupserver: Removing user1430609
07/16/12 20:36:45: urbackupserver: New Connection incomming 1431359 s: 368
07/16/12 20:36:45: Incoming data for client…
07/16/12 20:36:45: ClientService cmd: STATUS#pw=FLoaxlCsKZXrsGbnLVy4r4MB2PhuZ9
07/16/12 20:36:45: Incoming data for client…
07/16/12 20:36:45: rc=0 hasError=true state=0
07/16/12 20:36:45: urbackupserver: Removing user1431375
[/quote]

ximerian · July 17, 2012, 8:13pm

I just tried it on another 2003 server, this time one that isn’t a Small Business Server…same result.

These are all XenServer virtual machines, would that be the problem? I didn’t see anything about unsupported systems unless the drives were done with gparted.

It just worked on a Windows 7 machine, and on a server 2008. Could it be a problem with the latest version of the client on 2003?

uroni · July 17, 2012, 8:49pm

Hmm could be. The log above does only show the aftermath of the error though. Interesting would be what happens before that.

I even tested with XenServer once, so that should not be the problem. The volumes are standard NTFS volumes without software mirroring or software RAID?

ximerian · July 18, 2012, 3:49am

Pretty sure that was the entire log file. I kept renaming it so I could just select all and get everything relevant from the last change I tried.

They are standard NTFS drives, they -may- have been created originally with a Dell install disc instead of just the Windows one which -may- use gparted (I know it’s Linux based), but I doubt it. I inherited these servers and they’ve gone through a P2V conversion, but there isn’t any software mirroring or anything like that.

I have a clean install of 2003 in another VM that I didn’t want to dork with but I can try it there too I guess…if that one is buggered up I’m at a loss.

uroni · July 18, 2012, 3:20pm

If it does not contain any sensitive information could you send the whole debug log file to martin@urbackup.org ?

ximerian · July 19, 2012, 3:19pm

e-mail sent. Sorry it took so long, damn log was huge so I re-created it and let it run for a while

uroni · July 19, 2012, 7:55pm

No problem. And thanks!

I’m guessing these two lines are the problem:

07/19/12 10:12:54: ERROR: backupcom->GatherWriterMetadata(&pb_result) failed: EC=E_INVALIDARG
07/19/12 10:12:54: ERROR: Fatal exception. Crash dump written to "C:\WINDOWS\TEMP\UrBackup\v0.25.1-20120719-101254-3832-3828.dmp"

So the shadow copying thread crashes. I don’t know why it does not take the whole process down. That crash dump would be helpful, if you can send that to me.

Can you look if in “args.txt” it says

--plugin
urbackup_server03.dll

and not

--plugin
urbackup_xp.dll

?

ximerian · July 19, 2012, 10:21pm

It was using the XP one. I did that ‘just to see what would happen’ a night or two ago, it hasn’t been like that the whole time.

I sent another log after switching the plugin.

Thanks!!

uroni · July 20, 2012, 1:02pm

Okay. This is the error then:

07/19/12 17:59:12: ERROR: res!=VSS_S_ASYNC_FINISHED CCOM fail
07/19/12 17:59:12: ERROR: backupcom->GetSnapshotProperties(dir->ref->ssetid, &snap_props) failed: EC=VSS_E_OBJECT_NOT_FOUND

So somehow the shadow copying fails. Can you test if that is a general problem or an UrBackup specific one by entering

vssadmin create shadow /For=C:

in a command line?

On which service pack are you on?

ximerian · July 20, 2012, 2:56pm

Two of the servers I was testing on first were fully patched. The one the log is from has SP2 but is missing hotfixes.

vssadmin 1.1 - Volume Shadow Copy Service administrative command-line tool
(C) Copyright 2001 Microsoft Corp.  

Successfully created shadow copy for 'C:\'
    Shadow Copy ID: {8b369c7c-daa2-4705-b6c2-824cdf0576c3}
    Shadow Copy Volume Name: \\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy6

Is from the machine that the log is from.

I’ll look at the others and make sure it’s the same error on those ones too.

ximerian · July 20, 2012, 3:39pm

So I updated the XenServer PV drivers and now the backup is running!

These vms were P2V on 5.0, but now are running on 5.5 and it looks like I forgot to update the XenServer tools.

Image isn’t done yet, but it’s never even moved beyond 0% process before so I’m pretty optimistic.

Thanks for your patience and help, sorry to have wasted your time. Great product, I can’t wait to roll it out to all my clients.

It’s funny actually, only my test servers have the outdated tools. I just checked my production boxes and they are all updated properly…so by using test servers (old images from the production ones) I made this a lot harder than it needed to be.

luckman212 · May 23, 2013, 12:47pm

Did you ever figure this out? I’m also getting the “Pipe to client unexpectedly closed” error when trying to do an image backup but my client machine is a Win2008 server, and Urbackup version is now 1.2.1 x64. Not sure how to debug further!