Bacula-users
[Top] [All Lists]
<prev [Date] next>
[Advanced]
 <prev [Thread] next>

[Bacula-users] Bacula-SD frequently hangs

2008-04-22 05:37:55
Subject: [Bacula-users] Bacula-SD frequently hangs
From: Joern Koerner <koerner AT in.tu-clausthal DOT de>
To: bacula-users AT lists.sourceforge DOT net
Date: Tue, 22 Apr 2008 10:38:22 +0200 
Hi!

I've some really strange Problems with Bacula-SD.
For some unknown reason it frequently hangs while backing up Windows Clients. 
This does not happens on all the other Linux Clients.

When querying sd from bconsole, there will be no response.
When I restart SD, the currently inserted tape will be marked as ERROR, so 
I've to re-backup all the clients again and again...

Can anyone give me a hint to solve this issue, please?

Thanks in advise,
 Joern

Here's the debug output from bacula-sd:
---------------------------------------------
backup-server-sd: append.c:101-0 Just after acquire_device_for_append
backup-server-sd: bnet.c:264-0 TLS server negotiation established.
backup-server-sd: job.c:209-0 Running job anita_Files.2008-04-22_09.00.23
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=F set=R
backup-server-sd: jcr.c:623-0 OnExit JobStatus=R set=R
backup-server-sd: append.c:73-0 Start append data. res=3
backup-server-sd: askdir.c:230-0 >dird CatReq 
Job=anita_Files.2008-04-22_09.00.23 GetVolInfo VolName=S1TAPE12 write=1
backup-server-sd: askdir.c:182-0 <dird 1000 OK VolName=S1TAPE12 VolJobs=13 
VolFiles=104 VolBlocks=1597715 VolBytes=103071854592 VolMounts=1
 VolErrors=0 VolWrites=1597716 MaxVolBytes=0 VolCapacityBytes=0 
VolStatus=Append Slot=12 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime
=0 VolWriteTime=2379003517 EndFile=103 EndBlock=13719 VolParts=0 LabelType=0 
MediaId=37
backup-server-sd: askdir.c:205-0 do_reqest_vol_info return true slot=12 
Volume=S1TAPE12
backup-server-sd: askdir.c:341-0 Update cat VolFiles=104
backup-server-sd: askdir.c:364-0 >dird CatReq 
Job=anita_Files.2008-04-22_09.00.23 UpdateMedia VolName=S1TAPE12 VolJobs=14 
VolFiles=104 VolB
locks=1597715 VolBytes=103071854592 VolMounts=1 VolErrors=0 VolWrites=1597716 
MaxVolBytes=0 EndTime=1208847601 VolStatus=Append Slot=12 rel
abel=0 InChanger=1 VolReadTime=0 VolWriteTime=2379003517 VolFirstWritten=0 
VolParts=0
backup-server-sd: askdir.c:182-0 <dird 1000 OK VolName=S1TAPE12 VolJobs=14 
VolFiles=104 VolBlocks=1597715 VolBytes=103071854592 VolMounts=1
 VolErrors=0 VolWrites=1597716 MaxVolBytes=0 VolCapacityBytes=0 
VolStatus=Append Slot=12 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime
=0 VolWriteTime=2379003517 EndFile=103 EndBlock=13719 VolParts=0 LabelType=0 
MediaId=37
backup-server-sd: askdir.c:205-0 do_reqest_vol_info return true slot=12 
Volume=S1TAPE12
backup-server-sd: acquire.c:446-0 jid=1310 Dec reserve=2 dev="Drive-1" 
(/dev/nst0)
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=R set=R
backup-server-sd: jcr.c:623-0 OnExit JobStatus=R set=R
backup-server-sd: append.c:96-0 Begin append device="Drive-1" (/dev/nst0)
backup-server-sd: spool.c:110-0 Turning on data spooling
backup-server-sd: spool.c:179-0 Created spool 
file: 
/RAID/Spool/backup-server-sd.data.1310.anita_Files.2008-04-22_09.00.23.Drive-1.spool
backup-server-sd: append.c:101-0 Just after acquire_device_for_append
backup-server-sd: bnet.c:264-0 TLS server negotiation established.
backup-server-sd: job.c:209-0 Running job tumbelfalz_Files.2008-04-22_09.00.24
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=F set=R
backup-server-sd: jcr.c:623-0 OnExit JobStatus=R set=R
backup-server-sd: append.c:73-0 Start append data. res=2
backup-server-sd: askdir.c:230-0 >dird CatReq 
Job=tumbelfalz_Files.2008-04-22_09.00.24 GetVolInfo VolName=S1TAPE12 write=1
backup-server-sd: askdir.c:182-0 <dird 1000 OK VolName=S1TAPE12 VolJobs=14 
VolFiles=104 VolBlocks=1597715 VolBytes=103071854592 VolMounts=1
 VolErrors=0 VolWrites=1597716 MaxVolBytes=0 VolCapacityBytes=0 
VolStatus=Append Slot=12 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime
=0 VolWriteTime=2379003517 EndFile=103 EndBlock=13719 VolParts=0 LabelType=0 
MediaId=37
backup-server-sd: askdir.c:205-0 do_reqest_vol_info return true slot=12 
Volume=S1TAPE12
backup-server-sd: askdir.c:341-0 Update cat VolFiles=104
backup-server-sd: askdir.c:364-0 >dird CatReq 
Job=tumbelfalz_Files.2008-04-22_09.00.24 UpdateMedia VolName=S1TAPE12 
VolJobs=15 VolFiles=104
 VolBlocks=1597715 VolBytes=103071854592 VolMounts=1 VolErrors=0 
VolWrites=1597716 MaxVolBytes=0 EndTime=1208847601 VolStatus=Append Slot=1
2 relabel=0 InChanger=1 VolReadTime=0 VolWriteTime=2379003517 
VolFirstWritten=0 VolParts=0
backup-server-sd: askdir.c:182-0 <dird 1000 OK VolName=S1TAPE12 VolJobs=15 
VolFiles=104 VolBlocks=1597715 VolBytes=103071854592 VolMounts=1
 VolErrors=0 VolWrites=1597716 MaxVolBytes=0 VolCapacityBytes=0 
VolStatus=Append Slot=12 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime
=0 VolWriteTime=2379003517 EndFile=103 EndBlock=13719 VolParts=0 LabelType=0 
MediaId=37
backup-server-sd: askdir.c:205-0 do_reqest_vol_info return true slot=12 
Volume=S1TAPE12
backup-server-sd: acquire.c:446-0 jid=1311 Dec reserve=1 dev="Drive-1" 
(/dev/nst0)
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=R set=R
backup-server-sd: jcr.c:623-0 OnExit JobStatus=R set=R
backup-server-sd: append.c:96-0 Begin append device="Drive-1" (/dev/nst0)
backup-server-sd: spool.c:110-0 Turning on data spooling
backup-server-sd: spool.c:179-0 Created spool 
file: 
/RAID/Spool/backup-server-sd.data.1311.tumbelfalz_Files.2008-04-22_09.00.24.Drive-1.spo
ol
backup-server-sd: append.c:101-0 Just after acquire_device_for_append
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=R set=T
backup-server-sd: jcr.c:623-0 OnExit JobStatus=T set=T
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=T set=T
backup-server-sd: jcr.c:623-0 OnExit JobStatus=T set=T
backup-server-sd: append.c:300-0 back from write_end_session_label()
backup-server-sd: spool.c:138-0 Committing spooled data
backup-server-sd: spool.c:225-0 Despooling data
backup-server-sd: bnet.c:667-0 who=client host=127.0.1.1 port=36643
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=backup-server-sd: jcr.c:623-0 
OnExit JobStatus=C set=C
backup-server-sd: cram-md5.c:73-0 send: auth cram-md5 
<1653925484.1208847835@backup-server-sd> ssl=1
backup-server-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 
<1926337832.1208847835@backup-server-dir> ssl=2
backup-server-sd: cram-md5.c:152-0 sending resp to challenge: 
Bn/Rp9/cYk/QY74mN6Qf1C
backup-server-sd: bnet.c:264-0 TLS server negotiation established.
backup-server-sd: dircmd.c:207-0 Message channel init completed.
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=R set=A
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=A
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: mem_pool.c:418-0 Freed mem_pool count=34 size=74,250
backup-server-sd: bnet.c:667-0 who=client host=127.0.1.1 port=36643
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=backup-server-sd: jcr.c:623-0 
OnExit JobStatus=C set=C
backup-server-sd: cram-md5.c:73-0 send: auth cram-md5 
<1951368869.1208847836@backup-server-sd> ssl=1
backup-server-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 
<1434132781.1208847836@backup-server-dir> ssl=2
backup-server-sd: cram-md5.c:152-0 sending resp to challenge: 
F7xT36+ElR9Bq7c4hV/3gB
backup-server-sd: bnet.c:264-0 TLS server negotiation established.
backup-server-sd: dircmd.c:207-0 Message channel init completed.
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=R set=A
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=A
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: askdir.c:408-0 >dird CatReq 
Job=christine_Files.2008-04-22_09.00.20 CreateJobMedia FirstIndex=1 
LastIndex=264 StartFile=1
04 EndFile=104 StartBlock=0 EndBlock=15499 Copy=0 Strip=0 MediaId=37
backup-server-sd: askdir.c:415-0 <dird 1000 OK CreateJobMedia
backup-server-sd: askdir.c:341-0 Update cat VolFiles=105
backup-server-sd: askdir.c:364-0 >dird CatReq 
Job=christine_Files.2008-04-22_09.00.20 UpdateMedia VolName=S1TAPE12 
VolJobs=15 VolFiles=105
VolBlocks=1613215 VolBytes=104071790592 VolMounts=1 VolErrors=0 
VolWrites=1613216 MaxVolBytes=0 EndTime=1208847837 VolStatus=Append Slot=12
 relabel=0 InChanger=1 VolReadTime=0 VolWriteTime=2404091932 VolFirstWritten=0 
VolParts=0
backup-server-sd: askdir.c:182-0 <dird 1000 OK VolName=S1TAPE12 VolJobs=15 
VolFiles=105 VolBlocks=1613215 VolBytes=104071790592 VolMounts=1
 VolErrors=0 VolWrites=1613216 MaxVolBytes=0 VolCapacityBytes=0 
VolStatus=Append Slot=12 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime
=0 VolWriteTime=2404091932 EndFile=104 EndBlock=15499 VolParts=0 LabelType=0 
MediaId=37
backup-server-sd: askdir.c:205-0 do_reqest_vol_info return true slot=12 
Volume=S1TAPE12
backup-server-sd: block.c:807-0 dir_update_volume_info max file size -- OK
backup-server-sd: bnet.c:667-0 who=client host=127.0.1.1 port=36643
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=backup-server-sd: jcr.c:623-0 
OnExit JobStatus=C set=C
backup-server-sd: cram-md5.c:73-0 send: auth cram-md5 
<2009352776.1208847838@backup-server-sd> ssl=1
backup-server-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 
<1457720163.1208847838@backup-server-dir> ssl=2
backup-server-sd: cram-md5.c:152-0 sending resp to challenge: 
u99rSx+U13BTshZCi2cRzD
backup-server-sd: bnet.c:264-0 TLS server negotiation established.
backup-server-sd: dircmd.c:207-0 Message channel init completed.
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=R set=A
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=A
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: spool.c:371-0 EOT on spool read.
backup-server-sd: spool.c:204-0 Deleted spool 
file: 
/RAID/Spool/backup-server-sd.data.1307.christine_Files.2008-04-22_09.00.20.Drive-1.spoo
l
backup-server-sd: acquire.c:498-0 release_device device "Drive-1" (/dev/nst0) 
is tape
backup-server-sd: acquire.c:520-0 There are 3 writers in release_device
backup-server-sd: acquire.c:522-0 dir_create_jobmedia_record. Release
backup-server-sd: askdir.c:408-0 >dird CatReq 
Job=christine_Files.2008-04-22_09.00.20 CreateJobMedia FirstIndex=264 
LastIndex=384 StartFile
=105 EndFile=105 StartBlock=0 EndBlock=8613 Copy=0 Strip=0 MediaId=37
backup-server-sd: askdir.c:415-0 <dird 1000 OK CreateJobMedia
backup-server-sd: acquire.c:535-0 dir_update_vol_info. Release0
backup-server-sd: askdir.c:341-0 Update cat VolFiles=105
backup-server-sd: askdir.c:364-0 >dird CatReq 
Job=christine_Files.2008-04-22_09.00.20 UpdateMedia VolName=S1TAPE12 
VolJobs=15 VolFiles=105
VolBlocks=1621829 VolBytes=104627496960 VolMounts=1 VolErrors=0 
VolWrites=1621830 MaxVolBytes=0 EndTime=1208847845 VolStatus=Append Slot=12
 relabel=0 InChanger=1 VolReadTime=0 VolWriteTime=2408819143 VolFirstWritten=0 
VolParts=0
backup-server-sd: askdir.c:182-0 <dird 1000 OK VolName=S1TAPE12 VolJobs=15 
VolFiles=105 VolBlocks=1621829 VolBytes=104627496960 VolMounts=1
 VolErrors=0 VolWrites=1621830 MaxVolBytes=0 VolCapacityBytes=0 
VolStatus=Append Slot=12 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime
=0 VolWriteTime=2408819143 EndFile=105 EndBlock=8613 VolParts=0 LabelType=0 
MediaId=37
backup-server-sd: askdir.c:205-0 do_reqest_vol_info return true slot=12 
Volume=S1TAPE12
backup-server-sd: acquire.c:581-0 JobId=1307 broadcast wait_device_release
backup-server-sd: reserve.c:459-0 jid=1307 vol_unused: no vol on "Drive-1" 
(/dev/nst0)
backup-server-sd: reserve.c:181-0 jid=1307 List from dev busy cannot 
unreserve_volume: S1TAPE12 at 847c948 on device "Drive-1" (/dev/nst0)
backup-server-sd: acquire.c:596-0 ===== Device "Drive-1" (/dev/nst0) released 
by JobId=1307
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=T set=a
backup-server-sd: jcr.c:623-0 OnExit JobStatus=a set=a
backup-server-sd: append.c:339-0 return from do_append_data() ok=1
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=a set=T
backup-server-sd: jcr.c:623-0 OnExit JobStatus=T set=T
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: bnet.c:667-0 who=client host=127.0.1.1 port=36643
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=backup-server-sd: jcr.c:623-0 
OnExit JobStatus=C set=C
backup-server-sd: cram-md5.c:73-0 send: auth cram-md5 
<231369602.1208848210@backup-server-sd> ssl=1
backup-server-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 
<1381871437.1208848210@backup-server-dir> ssl=2
backup-server-sd: cram-md5.c:152-0 sending resp to challenge: 
GCxEO5/hj2wa84/pM+dlUA
backup-server-sd: bnet.c:264-0 TLS server negotiation established.
backup-server-sd: dircmd.c:207-0 Message channel init completed.
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=F set=A
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=A
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: reserve.c:427-0 jid=0 Dec reserve=0 dev="Drive-1" 
(/dev/nst0)
backup-server-sd: reserve.c:459-0 jid=1308 vol_unused: no vol on "Drive-1" 
(/dev/nst0)
backup-server-sd: reserve.c:181-0 jid=0 List from dev busy cannot 
unreserve_volume: S1TAPE12 at 847c948 on device "Drive-1" (/dev/nst0)
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=f
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=f
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=E
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=E
backup-server-sd: append.c:300-0 back from write_end_session_label()
backup-server-sd: spool.c:127-0 Data spooling discarded
backup-server-sd: spool.c:204-0 Deleted spool 
file: 
/RAID/Spool/backup-server-sd.data.1311.tumbelfalz_Files.2008-04-22_09.00.24.Drive-1.spo
ol
backup-server-sd: acquire.c:498-0 release_device device "Drive-1" (/dev/nst0) 
is tape
backup-server-sd: acquire.c:520-0 There are 2 writers in release_device
backup-server-sd: acquire.c:522-0 dir_create_jobmedia_record. Release
backup-server-sd: acquire.c:535-0 dir_update_vol_info. Release0
backup-server-sd: askdir.c:341-0 Update cat VolFiles=105
backup-server-sd: askdir.c:364-0 >dird CatReq 
Job=tumbelfalz_Files.2008-04-22_09.00.24 UpdateMedia VolName=S1TAPE12 
VolJobs=15 VolFiles=105
 VolBlocks=1621829 VolBytes=104627496960 VolMounts=1 VolErrors=0 
VolWrites=1621830 MaxVolBytes=0 EndTime=1208848790 VolStatus=Append Slot=1
2 relabel=0 InChanger=1 VolReadTime=0 VolWriteTime=2408819143 
VolFirstWritten=0 VolParts=0
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=f
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=f
backup-server-sd: askdir.c:370-0 Didn't get vol info vol=S1TAPE12: ERR=Network 
error on bnet_recv in req_vol_info.
backup-server-sd: acquire.c:581-0 JobId=1311 broadcast wait_device_release
backup-server-sd: reserve.c:459-0 jid=1311 vol_unused: no vol on "Drive-1" 
(/dev/nst0)
backup-server-sd: reserve.c:181-0 jid=1311 List from dev busy cannot 
unreserve_volume: S1TAPE12 at 847c948 on device "Drive-1" (/dev/nst0)
backup-server-sd: acquire.c:596-0 ===== Device "Drive-1" (/dev/nst0) released 
by JobId=1311
backup-server-sd: append.c:339-0 return from do_append_data() ok=0
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=E
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=E
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=T
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=T
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: openssl.c:85-0 jcr=0 TLS shutdown failure.: 
ERR=error:1409F07F:SSL routines:SSL3_WRITE_PENDING:bad write retry
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=f
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=f
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=E
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=E
backup-server-sd: append.c:300-0 back from write_end_session_label()
backup-server-sd: spool.c:127-0 Data spooling discarded
backup-server-sd: spool.c:204-0 Deleted spool 
file: 
/RAID/Spool/backup-server-sd.data.1309.gartenzwerg_Files.2008-04-22_09.00.22.Drive-1.sp
                                           
ool
backup-server-sd: acquire.c:498-0 release_device device "Drive-1" (/dev/nst0) 
is tape
backup-server-sd: acquire.c:520-0 There are 1 writers in release_device
backup-server-sd: acquire.c:522-0 dir_create_jobmedia_record. Release
backup-server-sd: acquire.c:535-0 dir_update_vol_info. Release0
backup-server-sd: askdir.c:341-0 Update cat VolFiles=105
backup-server-sd: askdir.c:364-0 >dird CatReq 
Job=gartenzwerg_Files.2008-04-22_09.00.22 UpdateMedia VolName=S1TAPE12 
VolJobs=15 VolFiles=10                                           5 
VolBlocks=1621829 VolBytes=104627496960 VolMounts=1 VolErrors=0 
VolWrites=1621830 MaxVolBytes=0 EndTime=1208848794 VolStatus=Append Slot=       
                                    
12 relabel=0 InChanger=1 VolReadTime=0 VolWriteTime=2408819143 
VolFirstWritten=0 VolParts=0
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=f
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=f
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=E
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=E
backup-server-sd: append.c:300-0 back from write_end_session_label()
backup-server-sd: spool.c:127-0 Data spooling discarded
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=f
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=f
backup-server-sd: askdir.c:370-0 Didn't get vol info vol=S1TAPE12: ERR=Network 
error on bnet_recv in req_vol_info.
backup-server-sd: acquire.c:581-0 JobId=1309 broadcast wait_device_release
backup-server-sd: reserve.c:459-0 jid=1309 vol_unused: no vol on "Drive-1" 
(/dev/nst0)
backup-server-sd: reserve.c:181-0 jid=1309 List from dev busy cannot 
unreserve_volume: S1TAPE12 at 847c948 on device "Drive-1" (/dev/nst0)
backup-server-sd: acquire.c:596-0 ===== Device "Drive-1" (/dev/nst0) released 
by JobId=1309
backup-server-sd: append.c:339-0 return from do_append_data() ok=0
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=E
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=E
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=A set=T
backup-server-sd: jcr.c:623-0 OnExit JobStatus=A set=T
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: pythonlib.c:237-0 No startup module.
backup-server-sd: spool.c:204-0 Deleted spool 
file: 
/RAID/Spool/backup-server-sd.data.1310.anita_Files.2008-04-22_09.00.23.Drive-1.spool
backup-server-sd: acquire.c:498-0 release_device device "Drive-1" (/dev/nst0) 
is tape
backup-server-sd: acquire.c:520-0 There are 0 writers in release_device
backup-server-sd: acquire.c:522-0 dir_create_jobmedia_record. Release
backup-server-sd: acquire.c:535-0 dir_update_vol_info. Release0
backup-server-sd: askdir.c:341-0 Update cat VolFiles=106
backup-server-sd: bnet.c:667-0 who=client host=127.0.1.1 port=36643
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=backup-server-sd: jcr.c:623-0 
OnExit JobStatus=C set=C
backup-server-sd: bnet.c:667-0 who=client host=127.0.1.1 port=36643
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=backup-server-sd: jcr.c:623-0 
OnExit JobStatus=C set=C
backup-server-sd: bnet.c:667-0 who=client host=127.0.1.1 port=36643
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=backup-server-sd: jcr.c:623-0 
OnExit JobStatus=C set=C
backup-server-sd: bnet.c:667-0 who=client host=127.0.1.1 port=36643
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=backup-server-sd: jcr.c:623-0 
OnExit JobStatus=C set=C
backup-server-sd: bnet.c:667-0 who=client host=127.0.1.1 port=36643
backup-server-sd: jcr.c:603-0 OnEntry JobStatus=backup-server-sd: jcr.c:623-0 
OnExit JobStatus=C set=C





Here're some Messages:
22-Apr 09:00 backup-server-dir JobId 1307: Start Backup JobId 1307, 
Job=christine_Files.2008-04-22_09.00.20
22-Apr 09:00 backup-server-dir JobId 1307: Using Device "Drive-1"
22-Apr 08:57 christine-fd JobId 1307: DIR and FD clocks differ by -133 
seconds, FD automatically compensating.
22-Apr 09:00 backup-server-sd JobId 1307: Spooling data ...
22-Apr 08:57 christine-fd JobId 1307: Generate VSS snapshots. Driver="VSS 
WinXP", Drive(s)="C"
22-Apr 09:00 christine-fd JobId 1307: VSS Writer (BackupComplete): "Microsoft 
Writer (Bootable State)", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 backup-server-sd JobId 1307: Job write elapsed time = 00:03:12, 
Transfer rate = 8.096 M bytes/second
22-Apr 09:00 christine-fd JobId 1307: VSS Writer 
(BackupComplete): "MSDEWriter", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 backup-server-sd JobId 1307: Committing spooled data to 
Volume "S1TAPE12". Despooling 1,555,928,294 bytes ...
22-Apr 09:00 christine-fd JobId 1307: VSS Writer (BackupComplete): "Microsoft 
Writer (Service State)", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:00 christine-fd JobId 1307: VSS Writer (BackupComplete): "WMI 
Writer", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:04 backup-server-sd JobId 1307: Despooling elapsed time = 00:00:43, 
Transfer rate = 36.18 M bytes/second
22-Apr 09:04 backup-server-sd JobId 1307: Sending spooled attrs to the 
Director. Despooling 138,817 bytes ...
22-Apr 09:04 backup-server-dir JobId 1307: Bacula backup-server-dir 2.2.8 
(26Jan08): 22-Apr-2008 09:04:12
  Build OS:               i686-pc-linux-gnu debian lenny/sid
  JobId:                  1307
  Job:                    christine_Files.2008-04-22_09.00.20
  Backup Level:           Incremental, since=2008-04-21 09:00:01
  Client:                 "christine-fd" 2.2.6 (10Nov07) 
Linux,Cross-compile,Win32
  FileSet:                "christine Full Set" 2008-02-04 09:00:00
  Pool:                   "Default" (From Job resource)
  Storage:                "Overland_Storage" (From Job resource)
  Scheduled time:         22-Apr-2008 09:00:00
  Start time:             22-Apr-2008 09:00:01
  End time:               22-Apr-2008 09:04:12
  Elapsed time:           4 mins 11 secs
  Priority:               10
  FD Files Written:       384
  SD Files Written:       384
  FD Bytes Written:       1,554,395,571 (1.554 GB)
  SD Bytes Written:       1,554,473,844 (1.554 GB)
  Rate:                   6192.8 KB/s
  Software Compression:   None
  VSS:                    yes
  Storage Encryption:     no
  Volume name(s):         S1TAPE12
  Volume Session Id:      17
  Volume Session Time:    1208760947
  Last Volume Bytes:      104,627,496,960 (104.6 GB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

22-Apr 09:04 backup-server-dir JobId 1307: Begin pruning Jobs.
22-Apr 09:04 backup-server-dir JobId 1307: No Jobs found to prune.
22-Apr 09:04 backup-server-dir JobId 1307: Begin pruning Files.
22-Apr 09:04 backup-server-dir JobId 1307: No Files found to prune.
22-Apr 09:04 backup-server-dir JobId 1307: End auto prune.
22-Apr 09:00 backup-server-dir JobId 1310: Start Backup JobId 1310, 
Job=anita_Files.2008-04-22_09.00.23
22-Apr 09:00 backup-server-dir JobId 1310: Using Device "Drive-1"
22-Apr 08:59 anita-fd JobId 1310: DIR and FD clocks differ by -5 seconds, FD 
automatically compensating.
22-Apr 09:00 backup-server-sd JobId 1310: Spooling data ...
22-Apr 08:59 anita-fd JobId 1310: Generate VSS snapshots. Driver="VSS WinXP", 
Drive(s)="C"
22-Apr 09:03 anita-fd JobId 1310: Fatal error: ../../filed/backup.c:892 
Network send error to SD. ERR=Input/output error
22-Apr 09:03 anita-fd JobId 1310: Error: ../../lib/bsock.c:311 Wrote 65536 
bytes to Storage daemon:backup-server.XYZ.de:9103, but only 49152 accepted.
22-Apr 09:03 anita-fd JobId 1310: VSS Writer (BackupComplete): "Microsoft 
Writer (Bootable State)", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 anita-fd JobId 1310: VSS Writer (BackupComplete): "Microsoft 
Writer (Service State)", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 anita-fd JobId 1310: VSS Writer (BackupComplete): "MSDEWriter", 
State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 anita-fd JobId 1310: VSS Writer (BackupComplete): "WMI Writer", 
State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 backup-server-sd JobId 1310: Job anita_Files.2008-04-22_09.00.23 
marked to be canceled.
22-Apr 09:04 backup-server-dir JobId 1310: Error: Bacula backup-server-dir 
2.2.8 (26Jan08): 22-Apr-2008 09:04:01
  Build OS:               i686-pc-linux-gnu debian lenny/sid
  JobId:                  1310
  Job:                    anita_Files.2008-04-22_09.00.23
  Backup Level:           Incremental, since=2008-04-21 09:00:00
  Client:                 "anita-fd" 2.2.6 (10Nov07) Linux,Cross-compile,Win32
  FileSet:                "anita Full Set" 2008-02-04 09:00:00
  Pool:                   "Default" (From Job resource)
  Storage:                "Overland_Storage" (From Job resource)
  Scheduled time:         22-Apr-2008 09:00:00
  Start time:             22-Apr-2008 09:00:01
  End time:               22-Apr-2008 09:04:01
  Elapsed time:           4 mins 
  Priority:               10
  FD Files Written:       139
  SD Files Written:       0
  FD Bytes Written:       1,111,875,650 (1.111 GB)
  SD Bytes Written:       0 (0 B)
  Rate:                   4632.8 KB/s
  Software Compression:   None
  VSS:                    yes
  Storage Encryption:     no
  Volume name(s):         
  Volume Session Id:      19
  Volume Session Time:    1208760947
  Last Volume Bytes:      104,071,790,592 (104.0 GB)
  Non-fatal FD errors:    1
  SD Errors:              0
  FD termination status:  Error
  SD termination status:  Error
  Termination:            *** Backup Error ***

22-Apr 09:19 backup-server-dir JobId 1310: Rescheduled Job 
anita_Files.2008-04-22_09.00.23 at 22-Apr-2008 09:19 to re-run in 3600 
seconds (22-Apr-2008 10:19).

22-Apr 09:00 backup-server-dir JobId 1311: Start Backup JobId 1311, 
Job=tumbelfalz_Files.2008-04-22_09.00.24
22-Apr 09:00 backup-server-dir JobId 1311: Using Device "Drive-1"
22-Apr 09:00 backup-server-sd JobId 1311: Spooling data ...
22-Apr 09:00 tumbelfalz-fd JobId 1311: Generate VSS snapshots. Driver="VSS 
WinXP", Drive(s)="C"
22-Apr 09:03 tumbelfalz-fd JobId 1311: Fatal error: ../../filed/backup.c:892 
Network send error to SD. ERR=Input/output error
22-Apr 09:03 tumbelfalz-fd JobId 1311: Error: ../../lib/bsock.c:311 Wrote 
65536 bytes to Storage daemon:backup-server.XYZ.de:9103, but only 49152 
accepted.
22-Apr 09:03 tumbelfalz-fd JobId 1311: VSS Writer 
(BackupComplete): "MSDEWriter", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 tumbelfalz-fd JobId 1311: VSS Writer (BackupComplete): "WMI 
Writer", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 tumbelfalz-fd JobId 1311: VSS Writer (BackupComplete): "Microsoft 
Writer (Bootable State)", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 tumbelfalz-fd JobId 1311: VSS Writer (BackupComplete): "Microsoft 
Writer (Service State)", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 backup-server-sd JobId 1311: Job 
tumbelfalz_Files.2008-04-22_09.00.24 marked to be canceled.
22-Apr 09:04 backup-server-dir JobId 1311: Error: Bacula backup-server-dir 
2.2.8 (26Jan08): 22-Apr-2008 09:04:00
  Build OS:               i686-pc-linux-gnu debian lenny/sid
  JobId:                  1311
  Job:                    tumbelfalz_Files.2008-04-22_09.00.24
  Backup Level:           Incremental, since=2008-04-21 12:02:39
  Client:                 "tumbelfalz-fd" 2.2.6 (10Nov07) 
Linux,Cross-compile,Win32
  FileSet:                "tumbelfalz Full Set" 2008-02-04 09:00:00
  Pool:                   "Default" (From Job resource)
  Storage:                "Overland_Storage" (From Job resource)
  Scheduled time:         22-Apr-2008 09:00:00
  Start time:             22-Apr-2008 09:00:01
  End time:               22-Apr-2008 09:04:00
  Elapsed time:           3 mins 59 secs
  Priority:               10
  FD Files Written:       332
  SD Files Written:       0
  FD Bytes Written:       860,608,816 (860.6 MB)
  SD Bytes Written:       0 (0 B)
  Rate:                   3600.9 KB/s
  Software Compression:   None
  VSS:                    yes
  Storage Encryption:     no
  Volume name(s):         
  Volume Session Id:      18
  Volume Session Time:    1208760947
  Last Volume Bytes:      104,071,790,592 (104.0 GB)
  Non-fatal FD errors:    1
  SD Errors:              0
  FD termination status:  Error
  SD termination status:  Error
  Termination:            *** Backup Error ***

22-Apr 09:04 backup-server-dir JobId 1311: Rescheduled Job 
tumbelfalz_Files.2008-04-22_09.00.24 at 22-Apr-2008 09:04 to re-run in 3600 
seconds (22-Apr-2008 10:04).

22-Apr 09:00 backup-server-dir JobId 1309: Start Backup JobId 1309, 
Job=gartenzwerg_Files.2008-04-22_09.00.22
22-Apr 09:00 backup-server-dir JobId 1309: Using Device "Drive-1"
22-Apr 09:00 gartenzwerg-fd JobId 1309: DIR and FD clocks differ by 5 seconds, 
FD automatically compensating.
22-Apr 09:00 backup-server-sd JobId 1309: Spooling data ...
22-Apr 09:00 gartenzwerg-fd JobId 1309: Generate VSS snapshots. Driver="VSS 
WinXP", Drive(s)="C"
22-Apr 09:04 gartenzwerg-fd JobId 1309: Fatal error: ../../filed/backup.c:1087 
Network send error to SD. ERR=Der Vorgang wurde erfolgreich beendet.

22-Apr 09:04 gartenzwerg-fd JobId 1309: Error: ../../lib/bsock.c:311 Wrote 139 
bytes to Storage daemon:backup-server.XYZ.de:9103, but only 0 accepted.
22-Apr 09:04 gartenzwerg-fd JobId 1309: VSS Writer 
(BackupComplete): "Microsoft Writer (Service State)", State: 0x1 
(VSS_WS_STABLE)
22-Apr 09:04 gartenzwerg-fd JobId 1309: VSS Writer 
(BackupComplete): "MSDEWriter", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:04 gartenzwerg-fd JobId 1309: VSS Writer 
(BackupComplete): "Microsoft Writer (Bootable State)", State: 0x1 
(VSS_WS_STABLE)
22-Apr 09:04 gartenzwerg-fd JobId 1309: VSS Writer (BackupComplete): "WMI 
Writer", State: 0x1 (VSS_WS_STABLE)
22-Apr 09:03 backup-server-sd JobId 1309: Job 
gartenzwerg_Files.2008-04-22_09.00.22 marked to be canceled.
22-Apr 09:04 backup-server-dir JobId 1309: Error: Bacula backup-server-dir 
2.2.8 (26Jan08): 22-Apr-2008 09:04:03
  Build OS:               i686-pc-linux-gnu debian lenny/sid
  JobId:                  1309
  Job:                    gartenzwerg_Files.2008-04-22_09.00.22
  Backup Level:           Incremental, since=2008-04-21 09:00:01
  Client:                 "gartenzwerg-fd" 2.2.6 (10Nov07) 
Linux,Cross-compile,Win32
  FileSet:                "gartenzwerg Full Set" 2008-02-04 09:00:00
  Pool:                   "Default" (From Job resource)
  Storage:                "Overland_Storage" (From Job resource)
  Scheduled time:         22-Apr-2008 09:00:00
  Start time:             22-Apr-2008 09:00:01
  End time:               22-Apr-2008 09:04:03
  Elapsed time:           4 mins 2 secs
  Priority:               10
  FD Files Written:       545
  SD Files Written:       0
  FD Bytes Written:       1,717,469,690 (1.717 GB)
  SD Bytes Written:       0 (0 B)
  Rate:                   7097.0 KB/s
  Software Compression:   None
  VSS:                    yes
  Storage Encryption:     no
  Volume name(s):         
  Volume Session Id:      16
  Volume Session Time:    1208760947
  Last Volume Bytes:      104,071,790,592 (104.0 GB)
  Non-fatal FD errors:    1
  SD Errors:              0
  FD termination status:  Error
  SD termination status:  Error
  Termination:            *** Backup Error ***

22-Apr 09:19 backup-server-dir JobId 1309: Rescheduled Job 
gartenzwerg_Files.2008-04-22_09.00.22 at 22-Apr-2008 09:19 to re-run in 3600 
seconds (22-Apr-2008 10:19).
22-Apr 10:33 backup-server-dir JobId 0: Fatal error: authenticate.c:113 
Director unable to authenticate with Storage daemon 
at "backup-server.XYZ.de:9103". Possible causes:
Passwords or names not the same or
Maximum Concurrent Jobs exceeded on the SD or
SD networking messed up (restart daemon).
Please see http://www.bacula.org/rel-manual/faq.html#AuthorizationErrors for 
help.

-------------------------------------------------------------------------
This SF.net email is sponsored by the 2008 JavaOne(SM) Conference 
Don't miss this year's exciting event. There's still time to save $100. 
Use priority code J8TL2D2. 
http://ad.doubleclick.net/clk;198757673;13503038;p?http://java.sun.com/javaone
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users
[More with this subject...]
<Prev in Thread] Current Thread [Next in Thread>
Previous by Date:  Re: [Bacula-users] bconsole can't connect to director, Bob Williams
Next by Date:  Re: [Bacula-users] duplicate full backups, Silver Salonen
Previous by Thread:  [Bacula-users] About Bacula's Windows client, xuxu
Next by Thread:  Re: [Bacula-users] Bacula-SD frequently hangs, Gunnar Thielebein
Indexes:  [Date] [Thread] [Top] [All Lists]