Hello, 14.11.2007 02:07,, Richard Walker wrote:: >> Do you see calls to dvd-handler in the SD's debug output? > > That's the thing - for the job that isn't working, there are calls to > get the free space, but not to do any writing.
Bad, but that's something to work on, I think. > I attach a file with some fresh results. It's broken up into sections > divided with lines of equals signs. > (I changed the hostname and job name but otherwise left the logs as they are.) > The sections are: > > 1. bconsole output of successful 65 MB backup. > 2. Output of ls showing successful write to DVD. > > At this point I edited the fileset to increase the backup to 9 GB and > restarted the director. > > 3. bconsole output of failed backup, showing where I typed the > cancel command. > 4. Output of ls showing contents of spool directory just before > I issued the cancel command. Notice multiple parts in the spool > directory! After cancelling the job, the last part increased in size > a little bit, but all parts are still there in the spool directory. Ok... that seems to indicate that Bacula itself does not handle writing the parts to DVD. The removal of the parts files is done by the SD, not dvd-handler. > 5. Debugging output of storage daemon showing both runs. Sorry, > I don't know exactly where the first run ends and the second begins, > but you can tell roughly by the references to jobid=22 versus > jobid=23. > > Note that the storage daemon debugging output clearly shows that > the first job calls dvd-handler to write the (only) part to DVD; the > second job never calls dvd-handler to do any writing. (As I noted > in the previous e-mail, I've also seen behaviour where cancelling > the job causes the _last_ part to be written, leaving the other parts > behind in the spool directory. But even that didn't happen this time.) So probably it's only the spacial case of a last part of less than the part size being written to DVD. The normal case seems to be missing then. I'll go through the output you sent... > 14-Nov 10:04 host1-dir JobId 22: No prior Full backup Job record found. > 14-Nov 10:04 host1-dir JobId 22: No prior or suitable Full backup found in > catalog. Doing FULL backup. > 14-Nov 10:04 host1-dir JobId 22: Start Backup JobId 22, > Job=xyz_projects.2007-11-14_10.04.05 > 14-Nov 10:04 host1-dir JobId 22: Created new Volume "BaculaDVD0002" in > catalog. > 14-Nov 10:04 host1-dir JobId 22: Using Device "DVDWriter" > 14-Nov 10:04 host1-sd JobId 22: Labeled new Volume "BaculaDVD0002" on device > "DVD Writer" (/dev/dvd). > 14-Nov 10:04 host1-sd JobId 22: Wrote label to prelabeled Volume > "BaculaDVD0002" on device "DVD Writer" (/dev/dvd) > 14-Nov 10:04 host1-sd JobId 22: Job write elapsed time = 00:00:05, Transfer > rate = 13.01 M bytes/second > * > 14-Nov 10:05 host1-sd JobId 22: Part 1 (65122629 bytes) written to DVD. > 14-Nov 10:05 host1-sd JobId 22: Remaining free space 4,624,384,000 on "DVD > Writer" (/dev/dvd) This looks perfect. > 14-Nov 10:05 host1-dir JobId 22: Bacula host1-dir 2.2.5 (09Oct07): > 14-Nov-2007 10:05:04 > Build OS: i686-redhat-linux-gnu redhat (Heidelberg) > JobId: 22 ... > Non-fatal FD errors: 0 > SD Errors: 0 > FD termination status: OK > SD termination status: OK > Termination: Backup OK ... > ====================================================================== > > ls -l /media/cdrecorder/ > total 63597 > -rw-r----- 1 root disk 65122419 Nov 14 10:04 BaculaDVD0002 > > ====================================================================== > > Job queued. JobId=23 > You have messages. > * > 14-Nov 11:24 host1-dir JobId 23: No prior Full backup Job record found. > 14-Nov 11:24 host1-dir JobId 23: No prior or suitable Full backup found in > catalog. Doing FULL backup. > 14-Nov 11:24 host1-dir JobId 23: Start Backup JobId 23, > Job=xyz_projects.2007-11-14_11.24.03 > 14-Nov 11:24 host1-dir JobId 23: Using Device "DVDWriter" > 14-Nov 11:24 host1-sd JobId 23: Volume "BaculaDVD0002" previously written, > moving to end of data. > 14-Nov 11:24 host1-sd JobId 23: Ready to append to end of Volume > "BaculaDVD0002" part=2 size=65122419 > *cancel > Automatically selected Job: JobId=23 Job=xyz_projects.2007-11-14_11.24.03 > Confirm cancel (yes/no): yes > 2001 Job xyz_projects.2007-11-14_11.24.03 marked to be canceled. > 3000 Job xyz_projects.2007-11-14_11.24.03 marked to be canceled. > * > 14-Nov 11:38 host1-sd JobId 23: Job xyz_projects.2007-11-14_11.24.03 marked > to be canceled. No writing to DVD here. ... > Last Volume Bytes: 4,018,574,700 (4.018 GB) But the volume size was increased... I don't know if this is actually taken from the DVD, or is generated by the SD as it adds up the part file sizes. I suspect the latter. > Non-fatal FD errors: 0 > SD Errors: 0 > FD termination status: Canceled > SD termination status: Canceled > Termination: Backup Canceled > > > ====================================================================== > > > -rw-r----- 1 root disk 838849486 Nov 14 11:28 BaculaDVD0002.2 > -rw-r----- 1 root disk 838849516 Nov 14 11:31 BaculaDVD0002.3 > -rw-r----- 1 root disk 838849509 Nov 14 11:34 BaculaDVD0002.4 > -rw-r----- 1 root disk 838849531 Nov 14 11:37 BaculaDVD0002.5 > -rw-r----- 1 root disk 513126400 Nov 14 11:38 BaculaDVD0002.6 As stated above, the existence of these files probably shows us that the SD doesn't actually handle writing the part files. > > ====================================================================== > > bacula-sd: stored_conf.c:675-0 Inserting director res: host1-mon > bacula-sd: stored_conf.c:675-0 Inserting device res: usbbackup01FileStorage > bacula-sd: stored_conf.c:675-0 Inserting device res: DVD Writer > host1-sd: jcr.c:132-0 read_last_jobs seek to 188 > host1-sd: jcr.c:139-0 Read num_items=9 > host1-sd: bpipe.c:371-0 Run program returning 0 > host1-sd: pythonlib.c:113-0 No script dir. prog=SDStartUp > host1-sd: jcr.c:603-0 OnEntry JobStatus=host1-sd: jcr.c:623-0 OnExit > JobStatus=C set=C > host1-sd: stored.c:480-0 calling init_dev /tmp/bactest > host1-sd: stored.c:482-0 SD init done /tmp/bactest > host1-sd: stored.c:480-0 calling init_dev /mnt/usbbackup01/bacula > host1-sd: dev.c:261-0 init_dev: tape=0 dev_name=/mnt/usbbackup01/bacula > host1-sd: stored.c:482-0 SD init done /mnt/usbbackup01/bacula > host1-sd: stored.c:480-0 calling init_dev /dev/dvd > host1-sd: dev.c:261-0 init_dev: tape=0 dev_name=/dev/dvd > host1-sd: stored.c:482-0 SD init done /dev/dvd > host1-sd: mem_pool.c:377-0 garbage collect memory pool > host1-sd: bnet_server.c:96-0 Addresses host[ipv4:0.0.0.0:9103] > host1-sd: bnet.c:666-0 who=client host=192.168.2.2 port=36643 > host1-sd: dircmd.c:172-0 Conn: Hello Director host1-dir calling > host1-sd: dircmd.c:185-0 Got a DIR connection > host1-sd: jcr.c:603-0 OnEntry JobStatus=host1-sd: jcr.c:623-0 OnExit > JobStatus=C set=C > host1-sd: cram-md5.c:73-0 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 > host1-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <[EMAIL > PROTECTED]> ssl=0 > host1-sd: cram-md5.c:152-0 sending resp to challenge: m8+C99Ba+V1l7D0h87IRPA > host1-sd: dircmd.c:207-0 Message channel init completed. > host1-sd: dircmd.c:214-0 <dird: JobId=22 job=xyz_projects.2007-11-14_10.04.05 > job_name=xyzprojects client_name=host1-fd type=66 level=70 > FileSet=xyzprojects NoAttr=0 SpoolAttr=0 FileSetMD5=tw/9LyQAS8YlQ75J54gx4D > SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 > > host1-sd: dircmd.c:228-0 Do command: JobId= > host1-sd: job.c:87-0 <dird: JobId=22 job=xyz_projects.2007-11-14_10.04.05 > job_name=xyzprojects client_name=host1-fd type=66 level=70 > FileSet=xyzprojects NoAttr=0 SpoolAttr=0 FileSetMD5=tw/9LyQAS8YlQ75J54gx4D > SpoolData=0 WritePartAfterJob=1 PreferMountedVols=1 > host1-sd: job.c:141-0 >dird jid=22: 3000 OK Job SDid=1 SDtime=1194995034 > Authorization=BABP-APHO-PHGK-OFKP-KEFK-KPPJ-BKCE-GJIA > host1-sd: pythonlib.c:237-0 No startup module. > host1-sd: dircmd.c:214-0 <dird: use storage=DVD media_type=DVD > pool_name=DVDPool pool_type=Backup append=1 copy=0 stripe=0 > > host1-sd: dircmd.c:228-0 Do command: use storage= > host1-sd: reserve.c:586-0 jid=22 <dird: use storage=DVD media_type=DVD > pool_name=DVDPool pool_type=Backup append=1 copy=0 stripe=0 > host1-sd: reserve.c:615-0 jid=22 <dird device: use device=DVDWriter > host1-sd: reserve.c:632-0 jid=22 Storage=DVD media_type=DVD pool=DVDPool > pool_type=Backup append=1 > host1-sd: reserve.c:634-0 jid=22 Device=DVD Writer > host1-sd: reserve.c:715-0 jid=22 PrefMnt=1 exact=1 suitable=0 chgronly=0 any=0 > host1-sd: reserve.c:828-0 jid=22 PrefMnt=1 exact=1 suitable=0 chgronly=0 > host1-sd: reserve.c:986-0 jid=22 search res for DVD Writer > host1-sd: reserve.c:1018-0 jid=22 Try match res=FileStorage > host1-sd: reserve.c:1018-0 jid=22 Try match res=usbbackup01FileStorage > host1-sd: reserve.c:1018-0 jid=22 Try match res=DVD Writer > host1-sd: reserve.c:1058-0 jid=22 chk MediaType device=DVD request=DVD > host1-sd: reserve.c:1081-0 jid=22 try reserve DVD Writer > host1-sd: reserve.c:1095-0 jid=22 have_vol=0 vol= > host1-sd: reserve.c:1254-0 jid=22 reserve_append device is "DVD Writer" > (/dev/dvd) > host1-sd: reserve.c:1286-0 jid=22 PrefMnt=1 exact=1 suitable=1 chgronly=0 > any=0 > host1-sd: reserve.c:1411-0 jid=22 OK Dev avail reserved "DVD Writer" > (/dev/dvd) > host1-sd: reserve.c:1264-0 jid=22 Inc reserve=1 dev="DVD Writer" (/dev/dvd) > 8bd2840 > host1-sd: reserve.c:1105-0 jid=22 Reserved=1 dev_name=DVD Writer > mediatype=DVD pool=DVDPool ok=1 > host1-sd: askdir.c:256-0 dir_find_next_appendable_volume > host1-sd: askdir.c:271-0 >dird: CatReq Job=xyz_projects.2007-11-14_10.04.05 > FindMedia=1 pool_name=DVDPool media_type=DVD > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=0 > VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 > MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=0 > MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 > VolParts=0 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: reserve.c:406-0 jid=22 find_vol=BaculaDVD0002 found=0 > host1-sd: reserve.c:532-0 jid=22 Vol=BaculaDVD0002 not in use. > host1-sd: reserve.c:313-0 jid=22 reserve_volume BaculaDVD0002 > host1-sd: reserve.c:238-0 jid=22 new Vol=BaculaDVD0002 at 8bd47c8 dev="DVD > Writer" (/dev/dvd) > host1-sd: reserve.c:181-0 jid=22 List from end new volume: BaculaDVD0002 at > 8bd47c8 on device "DVD Writer" (/dev/dvd) > host1-sd: reserve.c:1110-0 jid=22 looking for Volume=BaculaDVD0002 > host1-sd: reserve.c:1148-0 jid=22 >dird changer: 3000 OK use device > device=DVDWriter > host1-sd: reserve.c:1029-0 jid=22 Device DVD Writer reserved=1 for append. > host1-sd: reserve.c:959-0 jid=22 available device found=DVD Writer > host1-sd: dircmd.c:214-0 <dird: run > host1-sd: dircmd.c:228-0 Do command: run > host1-sd: job.c:156-0 Run_cmd: run > host1-sd: jcr.c:603-0 OnEntry JobStatus=C set=F > host1-sd: jcr.c:623-0 OnExit JobStatus=F set=F > host1-sd: job.c:175-0 xyz_projects.2007-11-14_10.04.05 waiting 1800 sec for > FD to contact SD key=BABP-APHO-PHGK-OFKP-KEFK-KPPJ-BKCE-GJIA > host1-sd: bnet.c:666-0 who=client host=192.168.2.2 port=36643 > host1-sd: dircmd.c:172-0 Conn: Hello Start Job > xyz_projects.2007-11-14_10.04.05 > host1-sd: dircmd.c:177-0 Got a FD connection > host1-sd: job.c:218-0 Found Job xyz_projects.2007-11-14_10.04.05 > host1-sd: cram-md5.c:73-0 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 > host1-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <[EMAIL > PROTECTED]> ssl=0 > host1-sd: cram-md5.c:152-0 sending resp to challenge: iR/itAkGQ4tLckMq8wMUuD > host1-sd: job.c:235-0 OK Authentication jid=22 Job > xyz_projects.2007-11-14_10.04.05 > host1-sd: job.c:194-0 Running job xyz_projects.2007-11-14_10.04.05 > host1-sd: fd_cmds.c:122-0 Start run Job=xyz_projects.2007-11-14_10.04.05 > host1-sd: jcr.c:603-0 OnEntry JobStatus=F set=R > host1-sd: jcr.c:623-0 OnExit JobStatus=R set=R > host1-sd: fd_cmds.c:160-0 <filed: append open session > host1-sd: fd_cmds.c:228-0 Append open session: append open session > host1-sd: fd_cmds.c:238-0 >filed: 3000 OK open ticket = 1 > host1-sd: fd_cmds.c:160-0 <filed: append data 1 > host1-sd: fd_cmds.c:190-0 Append data: append data 1 > host1-sd: fd_cmds.c:192-0 <bfiled: append data 1 > host1-sd: append.c:73-0 Start append data. res=1 > host1-sd: acquire.c:329-0 acquire_append device is DVD > host1-sd: acquire.c:418-0 Not in append mode, try mount. > host1-sd: acquire.c:424-0 Do mount_next_write_vol > host1-sd: mount.c:74-0 Enter mount_next_volume(release=0) dev="DVD Writer" > (/dev/dvd) > host1-sd: mount.c:84-0 mount_next_vol retry=0 > host1-sd: mount.c:110-0 Before dir_find_next_appendable_volume. > host1-sd: askdir.c:256-0 dir_find_next_appendable_volume > host1-sd: askdir.c:271-0 >dird: CatReq Job=xyz_projects.2007-11-14_10.04.05 > FindMedia=1 pool_name=DVDPool media_type=DVD > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=0 > VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 > MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=0 > MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 > VolParts=0 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: reserve.c:406-0 jid=22 find_vol=BaculaDVD0002 found=1 > host1-sd: reserve.c:181-0 jid=22 List from find_volume: BaculaDVD0002 at > 8bd47c8 on device "DVD Writer" (/dev/dvd) > host1-sd: reserve.c:538-0 jid=22 Vol=BaculaDVD0002 on same dev. > host1-sd: reserve.c:313-0 jid=22 reserve_volume BaculaDVD0002 > host1-sd: reserve.c:181-0 jid=22 List from begin reserve_volume: > BaculaDVD0002 at 8bd47c8 on device "DVD Writer" (/dev/dvd) > host1-sd: reserve.c:181-0 jid=22 List from end new volume: BaculaDVD0002 at > 8bd47c8 on device "DVD Writer" (/dev/dvd) > host1-sd: mount.c:122-0 After find_next_append. Vol=BaculaDVD0002 Slot=0 > Parts=0 > host1-sd: autochanger.c:121-0 Device "DVD Writer" (/dev/dvd) is not an > autochanger > host1-sd: mount.c:142-0 autoload_dev returns 0 > host1-sd: mount.c:158-0 Ask=0 autochanger=0 > host1-sd: mount.c:168-0 want vol=BaculaDVD0002 > host1-sd: dev.c:303-0 open dev: type=3 dev_name="DVD Writer" (/dev/dvd) > vol=BaculaDVD0002 mode=OPEN_READ_WRITE > host1-sd: dev.c:310-0 call open_dvd_device mode=OPEN_READ_WRITE > host1-sd: dev.c:518-0 Enter: open_dvd_dev: DVD vol= mode=OPEN_READ_WRITE > host1-sd: dev.c:529-0 Volume=BaculaDVD0002 > host1-sd: dev.c:541-0 Set part=1 > host1-sd: dev.c:554-0 open DVD part=1 num_dvd_parts=0 > host1-sd: dev.c:571-0 open_dvd_device: part=1 num_dvd_parts=0, > VolCatInfo.VolCatParts=0 > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dev.c:1992-0 do_mount: cmd=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder mounted=0 > host1-sd: dev.c:2004-0 do_mount run_prog=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder > host1-sd: dev.c:1983-0 ======= mount=0 > host1-sd: dev.c:2027-0 Device "DVD Writer" (/dev/dvd) cannot be mounted. > stat=268435488 result=mount: wrong fs type, bad option, bad superblock on > /dev/dvd, > or too many mounted file systems > ERR=Child exited with code 32 > host1-sd: dev.c:2071-0 do_mount: ignoring .. in /media/cdrecorder > host1-sd: dev.c:2071-0 do_mount: ignoring . in /media/cdrecorder > host1-sd: dev.c:2064-0 do_mount: failed to find suitable file in dir > /media/cdrecorder (dev="DVD Writer" (/dev/dvd)) > host1-sd: dev.c:2077-0 do_mount: got 0 files in the mount point (not counting > ., .. and .keep) > host1-sd: dev.c:2096-0 ============ mount=0 > host1-sd: dev.c:620-0 DVD device mount failed. > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dev.c:1992-0 do_mount: cmd=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder mounted=0 > host1-sd: dev.c:2004-0 do_mount run_prog=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder > host1-sd: dev.c:1983-0 ======= mount=0 > host1-sd: dev.c:2027-0 Device "DVD Writer" (/dev/dvd) cannot be mounted. > stat=268435488 result=mount: wrong fs type, bad option, bad superblock on > /dev/dvd, > or too many mounted file systems > ERR=Child exited with code 32 > host1-sd: dev.c:2071-0 do_mount: ignoring .. in /media/cdrecorder > host1-sd: dev.c:2071-0 do_mount: ignoring . in /media/cdrecorder > host1-sd: dev.c:2064-0 do_mount: failed to find suitable file in dir > /media/cdrecorder (dev="DVD Writer" (/dev/dvd)) > host1-sd: dev.c:2077-0 do_mount: got 0 files in the mount point (not counting > ., .. and .keep) > host1-sd: dev.c:2096-0 ============ mount=0 > host1-sd: dvd.c:118-0 update_freespace: cmd=/etc/bacula/dvd-handler /dev/dvd > free > host1-sd: dvd.c:127-0 Run freespace prog=/etc/bacula/dvd-handler /dev/dvd free > host1-sd: dvd.c:168-0 leave update_freespace: free_space=4689887232 > freespace_ok=1 free_space_errno=0 have_media=1 > host1-sd: dev.c:630-0 Could not mount device "DVD Writer" (/dev/dvd), this is > not a problem (num_dvd_parts == 0), and have media. > host1-sd: dev.c:647-0 open dev: DVD dev=/tmp/backup/BaculaDVD0002 > mode=OPEN_READ_WRITE part=1 npart=0 volcatnparts=0 > host1-sd: dev.c:649-0 openmode=2 OPEN_READ_WRITE > host1-sd: dev.c:654-0 mode=OPEN_READ_WRITE open(/tmp/backup/BaculaDVD0002, > 0x2, 0640) > host1-sd: dev.c:662-0 open failed: dev.c:659 Could not open: > /tmp/backup/BaculaDVD0002, ERR=No such file or directory > host1-sd: dev.c:672-0 Creating last part on spool: /tmp/backup/BaculaDVD0002 > host1-sd: dev.c:679-0 after open fd=6 > host1-sd: dev.c:317-0 preserve=0x0 fd=6 > host1-sd: label.c:81-0 Enter read_volume_label res=1 device="DVD Writer" > (/dev/dvd) vol=BaculaDVD0002 dev_Vol=*NULL* > host1-sd: label.c:149-0 Big if statement in read_volume_label > host1-sd: label.c:154-0 Requested Volume "BaculaDVD0002" on "DVD Writer" > (/dev/dvd) is not a Bacula labeled Volume, because: ERR=block.c:1008 Read > zero bytes at 0:0 on device "DVD Writer" (/dev/dvd). > host1-sd: label.c:178-0 No volume label - bailing out > host1-sd: label.c:262-0 return 3 > host1-sd: mount.c:237-0 Want dirVol=BaculaDVD0002 dirStat=Append > host1-sd: mount.c:509-0 Create volume label > host1-sd: label.c:315-0 write_volume_label() > host1-sd: label.c:330-0 New VolName=BaculaDVD0002 > host1-sd: label.c:337-0 Label type=0 > host1-sd: label.c:596-0 Start create_volume_label() > host1-sd: dev.c:1826-0 Clear volhdr vol= > > Volume Label: > Id : Bacula 1.0 immortal > VerNo : 11 > VolName : BaculaDVD0002 > PrevVolName : > VolFile : 0 > LabelType : PRE_LABEL > LabelSize : 0 > PoolName : DVDPool > MediaType : DVD > PoolType : Backup > HostName : host1.xxyyzz.xyz > Date label written: 14-Nov-2007 10:04 > host1-sd: label.c:584-0 Created Vol label rec: FI=PRE_LABEL len=174 > host1-sd: label.c:373-0 Wrote label of 174 bytes to "DVD Writer" (/dev/dvd) > host1-sd: label.c:376-0 Call write_block_to_dev() > host1-sd: label.c:391-0 Wrote block to device > host1-sd: dev.c:1636-0 weof_dev > > Volume Label: > Id : Bacula 1.0 immortal > VerNo : 11 > VolName : BaculaDVD0002 > PrevVolName : > VolFile : 0 > LabelType : PRE_LABEL > LabelSize : 0 > PoolName : DVDPool > MediaType : DVD > PoolType : Backup > HostName : host1.xxyyzz.xyz > Date label written: 14-Nov-2007 10:04 > host1-sd: reserve.c:313-0 jid=22 reserve_volume BaculaDVD0002 > host1-sd: reserve.c:181-0 jid=22 List from begin reserve_volume: > BaculaDVD0002 at 8bd47c8 on device "DVD Writer" (/dev/dvd) > host1-sd: reserve.c:181-0 jid=22 List from end new volume: BaculaDVD0002 at > 8bd47c8 on device "DVD Writer" (/dev/dvd) > host1-sd: mount.c:519-0 dir_update_vol_info. Set Append > host1-sd: askdir.c:339-0 Update cat VolFiles=0 > host1-sd: askdir.c:358-0 >dird: CatReq Job=xyz_projects.2007-11-14_10.04.05 > UpdateMedia VolName=BaculaDVD0002 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=0 > VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 EndTime=1194995055 > VolStatus=Append Slot=0 relabel=1 InChanger=0 VolReadTime=0 VolWriteTime=0 > VolFirstWritten=0 VolParts=0 > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=0 > VolFiles=0 VolBlocks=0 VolBytes=0 VolMounts=0 VolErrors=0 VolWrites=0 > MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=0 > MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 > VolParts=0 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: label.c:81-0 Enter read_volume_label res=1 device="DVD Writer" > (/dev/dvd) vol=BaculaDVD0002 dev_Vol=BaculaDVD0002 > host1-sd: label.c:104-0 Leave read_volume_label() VOL_OK > host1-sd: mount.c:237-0 Want dirVol=BaculaDVD0002 dirStat=Append > host1-sd: mount.c:244-0 Vol OK name=BaculaDVD0002 > host1-sd: label.c:430-0 set append found freshly labeled volume. fd=6 > dev=8bd2840 > host1-sd: label.c:279-0 write Label in write_volume_label_to_block() > host1-sd: label.c:584-0 Created Vol label rec: FI=VOL_LABEL len=174 > host1-sd: label.c:293-0 Wrote label of 174 bytes to block > host1-sd: label.c:482-0 Attempt to write to device fd=6. > host1-sd: label.c:506-0 dir_update_vol_info. Set Append > host1-sd: askdir.c:339-0 Update cat VolFiles=0 > host1-sd: askdir.c:358-0 >dird: CatReq Job=xyz_projects.2007-11-14_10.04.05 > UpdateMedia VolName=BaculaDVD0002 VolJobs=0 VolFiles=0 VolBlocks=0 > VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 > EndTime=1194995055 VolStatus=Append Slot=0 relabel=1 InChanger=0 > VolReadTime=0 VolWriteTime=7 VolFirstWritten=0 VolParts=0 > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=0 > VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 > MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=0 > MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=7 EndFile=0 EndBlock=0 > VolParts=0 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: label.c:522-0 OK from rewrite vol label. > host1-sd: mount.c:473-0 set APPEND, normal return from > mount_next_write_volume. dev="DVD Writer" (/dev/dvd) > host1-sd: acquire.c:436-0 Output pos=0:209 > host1-sd: askdir.c:339-0 Update cat VolFiles=0 > host1-sd: askdir.c:358-0 >dird: CatReq Job=xyz_projects.2007-11-14_10.04.05 > UpdateMedia VolName=BaculaDVD0002 VolJobs=1 VolFiles=0 VolBlocks=0 > VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 > EndTime=1194995055 VolStatus=Append Slot=0 relabel=0 InChanger=0 > VolReadTime=0 VolWriteTime=7 VolFirstWritten=0 VolParts=0 > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=1 > VolFiles=0 VolBlocks=0 VolBytes=210 VolMounts=1 VolErrors=0 VolWrites=1 > MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=0 > MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=7 EndFile=0 EndBlock=0 > VolParts=0 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: acquire.c:448-0 Dec reserve=0 dev="DVD Writer" (/dev/dvd) > host1-sd: jcr.c:603-0 OnEntry JobStatus=R set=R > host1-sd: jcr.c:623-0 OnExit JobStatus=R set=R > host1-sd: append.c:96-0 Begin append device="DVD Writer" (/dev/dvd) > host1-sd: append.c:101-0 Just after acquire_device_for_append > host1-sd: label.c:698-0 session_label record=8bd3658 > host1-sd: label.c:749-0 Write sesson_label record JobId=22 FI=SOS_LABEL > SessId=1 Strm=22 len=166 remainder=0 > host1-sd: label.c:753-0 Leave write_session_label Block=209d File=0d > host1-sd: jcr.c:603-0 OnEntry JobStatus=R set=T > host1-sd: jcr.c:623-0 OnExit JobStatus=T set=T > host1-sd: fd_cmds.c:160-0 <filed: append end session 1 > host1-sd: fd_cmds.c:210-0 store<file: append end session 1 > host1-sd: jcr.c:603-0 OnEntry JobStatus=T set=T > host1-sd: jcr.c:623-0 OnExit JobStatus=T set=T > host1-sd: fd_cmds.c:160-0 <filed: append close session 1 > host1-sd: fd_cmds.c:252-0 <filed: append close session 1 > host1-sd: fd_cmds.c:259-0 >filed: 3000 OK close Status = 84 > host1-sd: append.c:284-0 Write EOS label JobStatus=T > host1-sd: label.c:698-0 session_label record=8bd3658 > host1-sd: label.c:749-0 Write sesson_label record JobId=22 FI=EOS_LABEL > SessId=1 Strm=22 len=202 remainder=0 > host1-sd: label.c:753-0 Leave write_session_label Block=65092812d File=0d > host1-sd: append.c:300-0 back from write_end_session_label() > host1-sd: dvd.c:227-0 dvd_write_part: device is "DVD Writer" (/dev/dvd), part > is 1, is_mounted=0 > host1-sd: dvd.c:256-0 Write part: cmd=/etc/bacula/dvd-handler /dev/dvd write > 1 /tmp/backup/BaculaDVD0002 timeout=16000 > host1-sd: dvd.c:258-0 Write part status=0 result=Running > /opt/dvd+rw-tools-6.1.1/bin/growisofs Here the actual writing is taking place. > -use-the-force-luke=notray You might try commenting out this in dvd-handler - as far as I know, the linux kernel in some cases requires the reload to correctly process a disk that was written to. (Unfortunately, not all DVD drives are able to do the eject / load commands needed...) > -quiet -use-the-force-luke=4gms -A 'Bacula Data' -input-charset=default > -iso-level 3 -pad -p 'dvd-handler / growisofs' -sysid 'BACULADATA' -R -Z > /dev/dvd /tmp/backup/BaculaDVD0002 > Executing 'mkisofs -quiet -A Bacula Data -input-charset=default -iso-level 3 > -pad -p dvd-handler / growisofs -sysid BACULADATA -R > /tmp/backup/BaculaDVD0002 | builtin_dd of=/dev/dvd obs=32k seek=0' > /dev/dvd: "Current Write Speed" is 4.1x1385KBps. > /dev/dvd: flushing cache > /dev/dvd: stopping de-icing > /dev/dvd: writing lead-out > > Part file /tmp/backup/BaculaDVD0002 successfully written to disk. > > host1-sd: dvd.c:281-0 Update num_parts=1 > host1-sd: dvd.c:287-0 ========= unlink(/tmp/backup/BaculaDVD0002) > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dev.c:1992-0 do_mount: cmd=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder mounted=0 > host1-sd: dev.c:2004-0 do_mount run_prog=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dvd.c:118-0 update_freespace: cmd=/etc/bacula/dvd-handler /dev/dvd > free > host1-sd: dvd.c:127-0 Run freespace prog=/etc/bacula/dvd-handler /dev/dvd free > host1-sd: dvd.c:168-0 leave update_freespace: free_space=4624384000 > freespace_ok=1 free_space_errno=0 have_media=1 > host1-sd: dev.c:2107-0 ============ mount=1 > host1-sd: acquire.c:487-0 release_device device "DVD Writer" (/dev/dvd) is > disk > host1-sd: acquire.c:509-0 There are 0 writers in release_device > host1-sd: acquire.c:511-0 dir_create_jobmedia_record. Release > host1-sd: askdir.c:402-0 >dird: CatReq Job=xyz_projects.2007-11-14_10.04.05 > CreateJobMedia FirstIndex=1 LastIndex=601 StartFile=0 EndFile=0 > StartBlock=210 EndBlock=65122418 Copy=0 Strip=0 MediaId=12 > host1-sd: askdir.c:409-0 <dir: 1000 OK CreateJobMedia > host1-sd: dev.c:1636-0 weof_dev > host1-sd: acquire.c:524-0 dir_update_vol_info. Release0 > host1-sd: askdir.c:339-0 Update cat VolFiles=0 > host1-sd: askdir.c:358-0 >dird: CatReq Job=xyz_projects.2007-11-14_10.04.05 > UpdateMedia VolName=BaculaDVD0002 VolJobs=1 VolFiles=0 VolBlocks=1010 > VolBytes=65122419 VolMounts=1 VolErrors=0 VolWrites=1011 MaxVolBytes=0 > EndTime=1194995104 VolStatus=Append Slot=0 relabel=0 InChanger=0 > VolReadTime=0 VolWriteTime=218498 VolFirstWritten=0 VolParts=1 > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=1 > VolFiles=0 VolBlocks=1010 VolBytes=65122419 VolMounts=1 VolErrors=0 > VolWrites=1011 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 > MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=218498 > EndFile=0 EndBlock=65122418 VolParts=1 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: dev.c:1836-0 close_dev "DVD Writer" (/dev/dvd) > host1-sd: dev.c:1826-0 Clear volhdr vol=BaculaDVD0002 > host1-sd: acquire.c:570-0 JobId=22 broadcast wait_device_release > host1-sd: reserve.c:487-0 jid=22 free_volume BaculaDVD0002 dev="DVD Writer" > (/dev/dvd) > host1-sd: acquire.c:585-0 ===== Device "DVD Writer" (/dev/dvd) released by > JobId=22 > host1-sd: append.c:339-0 return from do_append_data() ok=1 > host1-sd: jcr.c:603-0 OnEntry JobStatus=T set=T > host1-sd: jcr.c:623-0 OnExit JobStatus=T set=T > host1-sd: pythonlib.c:237-0 No startup module. > host1-sd: dircmd.c:231-0 Command run reqeusts quit > host1-sd: pythonlib.c:237-0 No startup module. > host1-sd: mem_pool.c:377-0 garbage collect memory pool Anyway, this job ran fine. This trace can serve as a reference about what has to happen: SD reserving the device, verifying the disk available, not finding a label, labeling the blank disk, collecting data in a part file, and writing that to disk. ... Now on to the next job... > host1-sd: reserve.c:1411-0 jid=23 OK Dev avail reserved "DVD Writer" > (/dev/dvd) > host1-sd: reserve.c:1264-0 jid=23 Inc reserve=1 dev="DVD Writer" (/dev/dvd) > 8bd2840 > host1-sd: reserve.c:1105-0 jid=23 Reserved=1 dev_name=DVD Writer > mediatype=DVD pool=DVDPool ok=1 > host1-sd: askdir.c:256-0 dir_find_next_appendable_volume > host1-sd: askdir.c:271-0 >dird: CatReq Job=xyz_projects.2007-11-14_11.24.03 > FindMedia=1 pool_name=DVDPool media_type=DVD > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=1 > VolFiles=0 VolBlocks=1010 VolBytes=65122419 VolMounts=1 VolErrors=0 > VolWrites=1011 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 > MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=218498 > EndFile=0 EndBlock=65122418 VolParts=1 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: reserve.c:406-0 jid=23 find_vol=BaculaDVD0002 found=0 > host1-sd: reserve.c:532-0 jid=23 Vol=BaculaDVD0002 not in use. > host1-sd: reserve.c:313-0 jid=23 reserve_volume BaculaDVD0002 > host1-sd: reserve.c:238-0 jid=23 new Vol=BaculaDVD0002 at 8bd43d0 dev="DVD > Writer" (/dev/dvd) > host1-sd: reserve.c:181-0 jid=23 List from end new volume: BaculaDVD0002 at > 8bd43d0 on device "DVD Writer" (/dev/dvd) > host1-sd: reserve.c:1110-0 jid=23 looking for Volume=BaculaDVD0002 > host1-sd: reserve.c:1148-0 jid=23 >dird changer: 3000 OK use device > device=DVDWriter > host1-sd: reserve.c:1029-0 jid=23 Device DVD Writer reserved=1 for append. > host1-sd: reserve.c:959-0 jid=23 available device found=DVD Writer Here, the SD reserved the DVD writer and the volume known to be in it. > host1-sd: dircmd.c:214-0 <dird: run > host1-sd: dircmd.c:228-0 Do command: run > host1-sd: job.c:156-0 Run_cmd: run > host1-sd: jcr.c:603-0 OnEntry JobStatus=C set=F > host1-sd: jcr.c:623-0 OnExit JobStatus=F set=F > host1-sd: job.c:175-0 xyz_projects.2007-11-14_11.24.03 waiting 1800 sec for > FD to contact SD key=BBMA-KIGO-DBGI-JIID-DBLC-PMLK-MAAI-JOCC > host1-sd: bnet.c:666-0 who=client host=192.168.2.2 port=36643 > host1-sd: dircmd.c:172-0 Conn: Hello Start Job > xyz_projects.2007-11-14_11.24.03 > host1-sd: dircmd.c:177-0 Got a FD connection > host1-sd: job.c:218-0 Found Job xyz_projects.2007-11-14_11.24.03 > host1-sd: cram-md5.c:73-0 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 > host1-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <[EMAIL > PROTECTED]> ssl=0 > host1-sd: cram-md5.c:152-0 sending resp to challenge: O++c5V/6DBcV99+sd8dr+B > host1-sd: job.c:235-0 OK Authentication jid=23 Job > xyz_projects.2007-11-14_11.24.03 > host1-sd: job.c:194-0 Running job xyz_projects.2007-11-14_11.24.03 > host1-sd: fd_cmds.c:122-0 Start run Job=xyz_projects.2007-11-14_11.24.03 > host1-sd: jcr.c:603-0 OnEntry JobStatus=F set=R > host1-sd: jcr.c:623-0 OnExit JobStatus=R set=R > host1-sd: fd_cmds.c:160-0 <filed: append open session > host1-sd: fd_cmds.c:228-0 Append open session: append open session > host1-sd: fd_cmds.c:238-0 >filed: 3000 OK open ticket = 2 > host1-sd: fd_cmds.c:160-0 <filed: append data 2 > host1-sd: fd_cmds.c:190-0 Append data: append data 2 > host1-sd: fd_cmds.c:192-0 <bfiled: append data 2 > host1-sd: append.c:73-0 Start append data. res=1 > host1-sd: acquire.c:329-0 acquire_append device is DVD > host1-sd: acquire.c:418-0 Not in append mode, try mount. > host1-sd: acquire.c:424-0 Do mount_next_write_vol > host1-sd: mount.c:74-0 Enter mount_next_volume(release=0) dev="DVD Writer" > (/dev/dvd) > host1-sd: mount.c:84-0 mount_next_vol retry=0 > host1-sd: mount.c:110-0 Before dir_find_next_appendable_volume. > host1-sd: askdir.c:256-0 dir_find_next_appendable_volume > host1-sd: askdir.c:271-0 >dird: CatReq Job=xyz_projects.2007-11-14_11.24.03 > FindMedia=1 pool_name=DVDPool media_type=DVD > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=1 > VolFiles=0 VolBlocks=1010 VolBytes=65122419 VolMounts=1 VolErrors=0 > VolWrites=1011 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 > MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=218498 > EndFile=0 EndBlock=65122418 VolParts=1 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: reserve.c:406-0 jid=23 find_vol=BaculaDVD0002 found=1 > host1-sd: reserve.c:181-0 jid=23 List from find_volume: BaculaDVD0002 at > 8bd43d0 on device "DVD Writer" (/dev/dvd) > host1-sd: reserve.c:538-0 jid=23 Vol=BaculaDVD0002 on same dev. > host1-sd: reserve.c:313-0 jid=23 reserve_volume BaculaDVD0002 > host1-sd: reserve.c:181-0 jid=23 List from begin reserve_volume: > BaculaDVD0002 at 8bd43d0 on device "DVD Writer" (/dev/dvd) > host1-sd: reserve.c:181-0 jid=23 List from end new volume: BaculaDVD0002 at > 8bd43d0 on device "DVD Writer" (/dev/dvd) > host1-sd: mount.c:122-0 After find_next_append. Vol=BaculaDVD0002 Slot=0 > Parts=1 > host1-sd: autochanger.c:121-0 Device "DVD Writer" (/dev/dvd) is not an > autochanger > host1-sd: mount.c:142-0 autoload_dev returns 0 > host1-sd: mount.c:158-0 Ask=0 autochanger=0 > host1-sd: mount.c:168-0 want vol=BaculaDVD0002 > host1-sd: dev.c:303-0 open dev: type=3 dev_name="DVD Writer" (/dev/dvd) > vol=BaculaDVD0002 mode=OPEN_READ_WRITE > host1-sd: dev.c:310-0 call open_dvd_device mode=OPEN_READ_WRITE > host1-sd: dev.c:518-0 Enter: open_dvd_dev: DVD vol= mode=OPEN_READ_WRITE > host1-sd: dev.c:529-0 Volume=BaculaDVD0002 > host1-sd: dev.c:554-0 open DVD part=1 num_dvd_parts=1 > host1-sd: dev.c:571-0 open_dvd_device: part=1 num_dvd_parts=1, > VolCatInfo.VolCatParts=1 > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dev.c:1992-0 do_mount: cmd=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder mounted=0 > host1-sd: dev.c:2004-0 do_mount run_prog=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dvd.c:118-0 update_freespace: cmd=/etc/bacula/dvd-handler /dev/dvd > free > host1-sd: dvd.c:127-0 Run freespace prog=/etc/bacula/dvd-handler /dev/dvd free > host1-sd: dvd.c:168-0 leave update_freespace: free_space=4624384000 > freespace_ok=1 free_space_errno=0 have_media=1 > host1-sd: dev.c:2107-0 ============ mount=1 > host1-sd: dev.c:574-0 DVD device mounted. > host1-sd: dev.c:647-0 open dev: DVD dev=/media/cdrecorder/BaculaDVD0002 > mode=OPEN_READ_ONLY part=1 npart=1 volcatnparts=1 > host1-sd: dev.c:649-0 openmode=3 OPEN_READ_ONLY > host1-sd: dev.c:654-0 mode=OPEN_READ_ONLY > open(/media/cdrecorder/BaculaDVD0002, 0x0, 0640) > host1-sd: dev.c:679-0 after open fd=6 > host1-sd: dev.c:317-0 preserve=0x0 fd=6 > host1-sd: dev.c:294-0 Close fd for mode change. > host1-sd: dev.c:303-0 open dev: type=3 dev_name="DVD Writer" (/dev/dvd) > vol=BaculaDVD0002 mode=OPEN_READ_WRITE > host1-sd: dev.c:310-0 call open_dvd_device mode=OPEN_READ_WRITE > host1-sd: dev.c:518-0 Enter: open_dvd_dev: DVD vol= mode=OPEN_READ_WRITE > host1-sd: dev.c:529-0 Volume=BaculaDVD0002 > host1-sd: dev.c:554-0 open DVD part=1 num_dvd_parts=1 > host1-sd: dev.c:571-0 open_dvd_device: part=1 num_dvd_parts=1, > VolCatInfo.VolCatParts=1 > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dev.c:574-0 DVD device mounted. > host1-sd: dev.c:647-0 open dev: DVD dev=/media/cdrecorder/BaculaDVD0002 > mode=OPEN_READ_ONLY part=1 npart=1 volcatnparts=1 > host1-sd: dev.c:649-0 openmode=3 OPEN_READ_ONLY > host1-sd: dev.c:654-0 mode=OPEN_READ_ONLY > open(/media/cdrecorder/BaculaDVD0002, 0x0, 0640) > host1-sd: dev.c:679-0 after open fd=6 > host1-sd: dev.c:317-0 preserve=0x0 fd=6 > host1-sd: label.c:81-0 Enter read_volume_label res=1 device="DVD Writer" > (/dev/dvd) vol=BaculaDVD0002 dev_Vol=*NULL* > host1-sd: label.c:149-0 Big if statement in read_volume_label > host1-sd: label.c:815-0 unser_vol_label > > Volume Label: > Id : Bacula 1.0 immortal > VerNo : 11 > VolName : BaculaDVD0002 > PrevVolName : > VolFile : 0 > LabelType : VOL_LABEL > LabelSize : 174 > PoolName : DVDPool > MediaType : DVD > PoolType : Backup > HostName : host1.xxyyzz.xyz > Date label written: 14-Nov-2007 10:04 > host1-sd: reserve.c:313-0 jid=23 reserve_volume BaculaDVD0002 > host1-sd: reserve.c:181-0 jid=23 List from begin reserve_volume: > BaculaDVD0002 at 8bd43d0 on device "DVD Writer" (/dev/dvd) > host1-sd: reserve.c:181-0 jid=23 List from end new volume: BaculaDVD0002 at > 8bd43d0 on device "DVD Writer" (/dev/dvd) > host1-sd: label.c:223-0 Compare Vol names: VolName=BaculaDVD0002 > hdr=BaculaDVD0002 > host1-sd: label.c:239-0 Copy vol_name=BaculaDVD0002 > > Volume Label: > Id : Bacula 1.0 immortal > VerNo : 11 > VolName : BaculaDVD0002 > PrevVolName : > VolFile : 0 > LabelType : VOL_LABEL > LabelSize : 174 > PoolName : DVDPool > MediaType : DVD > PoolType : Backup > HostName : host1.xxyyzz.xyz > Date label written: 14-Nov-2007 10:04 > host1-sd: label.c:244-0 Leave read_volume_label() VOL_OK > host1-sd: mount.c:237-0 Want dirVol=BaculaDVD0002 dirStat=Append > host1-sd: mount.c:244-0 Vol OK name=BaculaDVD0002 > host1-sd: mount.c:376-0 Device previously written, moving to end of data > host1-sd: dev.c:838-0 eod > host1-sd: dvd.c:408-0 Enter: ==== open_first_part dev="DVD Writer" (/dev/dvd) > Vol=BaculaDVD0002 mode=3 num_dvd_parts=1 append=0 > host1-sd: dev.c:1836-0 close_dev "DVD Writer" (/dev/dvd) > host1-sd: dev.c:1826-0 Clear volhdr vol=BaculaDVD0002 > host1-sd: dvd.c:415-0 Set part=1 > host1-sd: dev.c:303-0 open dev: type=3 dev_name="DVD Writer" (/dev/dvd) > vol=BaculaDVD0002 mode=OPEN_READ_ONLY > host1-sd: dev.c:310-0 call open_dvd_device mode=OPEN_READ_ONLY > host1-sd: dev.c:518-0 Enter: open_dvd_dev: DVD vol= mode=OPEN_READ_ONLY > host1-sd: dev.c:529-0 Volume=BaculaDVD0002 > host1-sd: dev.c:554-0 open DVD part=1 num_dvd_parts=1 > host1-sd: dev.c:571-0 open_dvd_device: part=1 num_dvd_parts=1, > VolCatInfo.VolCatParts=1 > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dev.c:1992-0 do_mount: cmd=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder mounted=0 > host1-sd: dev.c:2004-0 do_mount run_prog=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dvd.c:118-0 update_freespace: cmd=/etc/bacula/dvd-handler /dev/dvd > free > host1-sd: dvd.c:127-0 Run freespace prog=/etc/bacula/dvd-handler /dev/dvd free > host1-sd: dvd.c:168-0 leave update_freespace: free_space=4624384000 > freespace_ok=1 free_space_errno=0 have_media=1 > host1-sd: dev.c:2107-0 ============ mount=1 > host1-sd: dev.c:574-0 DVD device mounted. > host1-sd: dev.c:647-0 open dev: DVD dev=/media/cdrecorder/BaculaDVD0002 > mode=OPEN_READ_ONLY part=1 npart=1 volcatnparts=1 > host1-sd: dev.c:649-0 openmode=3 OPEN_READ_ONLY > host1-sd: dev.c:654-0 mode=OPEN_READ_ONLY > open(/media/cdrecorder/BaculaDVD0002, 0x0, 0640) > host1-sd: dev.c:679-0 after open fd=6 > host1-sd: dev.c:317-0 preserve=0x0 fd=6 > host1-sd: dvd.c:311-0 Enter: == open_next_part part=1 npart=1 dev="DVD > Writer" (/dev/dvd) vol=BaculaDVD0002 mode=3 file_addr=0 > host1-sd: dev.c:1836-0 close_dev "DVD Writer" (/dev/dvd) > host1-sd: dev.c:1826-0 Clear volhdr vol=BaculaDVD0002 > host1-sd: dvd.c:341-0 Inc part=2 num_dvd_parts=1 > host1-sd: dvd.c:355-0 Check if part on DVD: /media/cdrecorder/BaculaDVD0002.2 > host1-sd: dev.c:303-0 open dev: type=3 dev_name="DVD Writer" (/dev/dvd) > vol=BaculaDVD0002 mode=OPEN_READ_ONLY > host1-sd: dev.c:310-0 call open_dvd_device mode=OPEN_READ_ONLY > host1-sd: dev.c:518-0 Enter: open_dvd_dev: DVD vol= mode=OPEN_READ_ONLY > host1-sd: dev.c:529-0 Volume=BaculaDVD0002 > host1-sd: dev.c:554-0 open DVD part=2 num_dvd_parts=1 > host1-sd: dev.c:571-0 open_dvd_device: part=2 num_dvd_parts=1, > VolCatInfo.VolCatParts=1 > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dev.c:1992-0 do_mount: cmd=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder mounted=0 > host1-sd: dev.c:2004-0 do_mount run_prog=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dvd.c:118-0 update_freespace: cmd=/etc/bacula/dvd-handler /dev/dvd > free > host1-sd: dvd.c:127-0 Run freespace prog=/etc/bacula/dvd-handler /dev/dvd free > host1-sd: dvd.c:168-0 leave update_freespace: free_space=4624384000 > freespace_ok=1 free_space_errno=0 have_media=1 > host1-sd: dev.c:2107-0 ============ mount=1 > host1-sd: dev.c:574-0 DVD device mounted. > host1-sd: dev.c:647-0 open dev: DVD dev=/tmp/backup/BaculaDVD0002.2 > mode=OPEN_READ_WRITE part=2 npart=1 volcatnparts=1 > host1-sd: dev.c:649-0 openmode=2 OPEN_READ_WRITE > host1-sd: dev.c:654-0 mode=OPEN_READ_WRITE open(/tmp/backup/BaculaDVD0002.2, > 0x2, 0640) > host1-sd: dev.c:662-0 open failed: dev.c:659 Could not open: > /tmp/backup/BaculaDVD0002.2, ERR=No such file or directory > host1-sd: dev.c:672-0 Creating last part on spool: /tmp/backup/BaculaDVD0002.2 Ok, here the SD created the second part file, after verifying the current DVD contents. This is correct, so far. > host1-sd: dev.c:679-0 after open fd=6 > host1-sd: dev.c:317-0 preserve=0x0 fd=6 > host1-sd: mount.c:434-0 update volinfo mounts=2 > host1-sd: askdir.c:339-0 Update cat VolFiles=0 > host1-sd: askdir.c:358-0 >dird: CatReq Job=xyz_projects.2007-11-14_11.24.03 > UpdateMedia VolName=BaculaDVD0002 VolJobs=1 VolFiles=0 VolBlocks=1010 > VolBytes=65122419 VolMounts=2 VolErrors=0 VolWrites=1011 MaxVolBytes=0 > EndTime=1194999857 VolStatus=Append Slot=0 relabel=0 InChanger=0 > VolReadTime=0 VolWriteTime=218498 VolFirstWritten=0 VolParts=1 > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=1 > VolFiles=0 VolBlocks=1010 VolBytes=65122419 VolMounts=2 VolErrors=0 > VolWrites=1011 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 > MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=218498 > EndFile=0 EndBlock=65122418 VolParts=1 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: mount.c:473-0 set APPEND, normal return from > mount_next_write_volume. dev="DVD Writer" (/dev/dvd) > host1-sd: acquire.c:436-0 Output pos=0:65122419 > host1-sd: askdir.c:339-0 Update cat VolFiles=0 > host1-sd: askdir.c:358-0 >dird: CatReq Job=xyz_projects.2007-11-14_11.24.03 > UpdateMedia VolName=BaculaDVD0002 VolJobs=2 VolFiles=0 VolBlocks=1010 > VolBytes=65122419 VolMounts=2 VolErrors=0 VolWrites=1011 MaxVolBytes=0 > EndTime=1194999857 VolStatus=Append Slot=0 relabel=0 InChanger=0 > VolReadTime=0 VolWriteTime=218498 VolFirstWritten=0 VolParts=1 > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=2 > VolFiles=0 VolBlocks=1010 VolBytes=65122419 VolMounts=2 VolErrors=0 > VolWrites=1011 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 > MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=218498 > EndFile=0 EndBlock=65122418 VolParts=1 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: acquire.c:448-0 Dec reserve=0 dev="DVD Writer" (/dev/dvd) > host1-sd: jcr.c:603-0 OnEntry JobStatus=R set=R > host1-sd: jcr.c:623-0 OnExit JobStatus=R set=R > host1-sd: append.c:96-0 Begin append device="DVD Writer" (/dev/dvd) > host1-sd: append.c:101-0 Just after acquire_device_for_append > host1-sd: label.c:698-0 session_label record=8bde428 > host1-sd: label.c:749-0 Write sesson_label record JobId=23 FI=SOS_LABEL > SessId=2 Strm=23 len=166 remainder=0 > host1-sd: label.c:753-0 Leave write_session_label Block=65122419d File=0d > host1-sd: dvd.c:311-0 Enter: == open_next_part part=2 npart=1 dev="DVD > Writer" (/dev/dvd) vol=BaculaDVD0002 mode=2 file_addr=903971905 > host1-sd: dev.c:1836-0 close_dev "DVD Writer" (/dev/dvd) > host1-sd: dev.c:1826-0 Clear volhdr vol=BaculaDVD0002 > host1-sd: dvd.c:341-0 Inc part=3 num_dvd_parts=1 > host1-sd: dvd.c:355-0 Check if part on DVD: /media/cdrecorder/BaculaDVD0002.3 And now it's already working on part .3. Somewhere in between, data should have been written to DVD but that didn't happen. In fact no calls of dvd-handler. > host1-sd: dev.c:303-0 open dev: type=3 dev_name="DVD Writer" (/dev/dvd) > vol=BaculaDVD0002 mode=OPEN_READ_ONLY > host1-sd: dev.c:310-0 call open_dvd_device mode=OPEN_READ_ONLY > host1-sd: dev.c:518-0 Enter: open_dvd_dev: DVD vol= mode=OPEN_READ_ONLY > host1-sd: dev.c:529-0 Volume=BaculaDVD0002 > host1-sd: dev.c:554-0 open DVD part=3 num_dvd_parts=1 > host1-sd: dev.c:571-0 open_dvd_device: part=3 num_dvd_parts=1, > VolCatInfo.VolCatParts=1 > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dev.c:1992-0 do_mount: cmd=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder mounted=0 > host1-sd: dev.c:2004-0 do_mount run_prog=/bin/mount -t iso9660 -o ro /dev/dvd > /media/cdrecorder > host1-sd: dev.c:1944-0 Enter mount > host1-sd: dvd.c:118-0 update_freespace: cmd=/etc/bacula/dvd-handler /dev/dvd > free > host1-sd: dvd.c:127-0 Run freespace prog=/etc/bacula/dvd-handler /dev/dvd free > host1-sd: dvd.c:168-0 leave update_freespace: free_space=4624384000 > freespace_ok=1 free_space_errno=0 have_media=1 > host1-sd: dev.c:2107-0 ============ mount=1 > host1-sd: dev.c:574-0 DVD device mounted. > host1-sd: dev.c:647-0 open dev: DVD dev=/tmp/backup/BaculaDVD0002.3 > mode=OPEN_READ_WRITE part=3 npart=1 volcatnparts=1 Verifying part three is usable, and so on... I'll skip much of the following log. ... > host1-sd: dev.c:672-0 Creating last part on spool: /tmp/backup/BaculaDVD0002.6 Now the last part of this job. > host1-sd: dev.c:679-0 after open fd=6 > host1-sd: dev.c:317-0 preserve=0x0 fd=6 > host1-sd: askdir.c:339-0 Update cat VolFiles=0 > host1-sd: askdir.c:358-0 >dird: CatReq Job=xyz_projects.2007-11-14_11.24.03 > UpdateMedia VolName=BaculaDVD0002 VolJobs=2 VolFiles=0 VolBlocks=53022 > VolBytes=3420520461 VolMounts=2 VolErrors=0 VolWrites=53023 MaxVolBytes=0 > EndTime=1195000636 VolStatus=Append Slot=0 relabel=0 InChanger=0 > VolReadTime=0 VolWriteTime=21216363 VolFirstWritten=0 VolParts=1 > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=2 > VolFiles=0 VolBlocks=53022 VolBytes=3420520461 VolMounts=2 VolErrors=0 > VolWrites=53023 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 > MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=21216363 > EndFile=0 EndBlock=65122418 VolParts=1 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: bnet.c:666-0 who=client host=192.168.2.2 port=36643 > host1-sd: dircmd.c:172-0 Conn: Hello Director host1-dir calling > host1-sd: dircmd.c:185-0 Got a DIR connection > host1-sd: jcr.c:603-0 OnEntry JobStatus=host1-sd: jcr.c:623-0 OnExit > JobStatus=C set=C > host1-sd: cram-md5.c:73-0 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 > host1-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <[EMAIL > PROTECTED]> ssl=0 > host1-sd: cram-md5.c:152-0 sending resp to challenge: IgAMW8/nM7+Bo8guT+QlvB > host1-sd: dircmd.c:207-0 Message channel init completed. > host1-sd: dircmd.c:214-0 <dird: cancel Job=xyz_projects.2007-11-14_11.24.03 > > host1-sd: dircmd.c:228-0 Do command: cancel > host1-sd: jcr.c:603-0 OnEntry JobStatus=R set=A > host1-sd: jcr.c:623-0 OnExit JobStatus=A set=A > host1-sd: pythonlib.c:237-0 No startup module. > host1-sd: mem_pool.c:377-0 garbage collect memory pool > host1-sd: bnet.c:666-0 who=client host=192.168.2.2 port=36643 > host1-sd: jcr.c:603-0 OnEntry JobStatus=A set=f > host1-sd: jcr.c:623-0 OnExit JobStatus=A set=f > host1-sd: jcr.c:603-0 OnEntry JobStatus=A set=E > host1-sd: jcr.c:623-0 OnExit JobStatus=A set=E > host1-sd: append.c:284-0 Write EOS label JobStatus=A The end of session label... > host1-sd: label.c:698-0 session_label record=8bde548 > host1-sd: label.c:749-0 Write sesson_label record JobId=23 FI=EOS_LABEL > SessId=2 Strm=23 len=202 remainder=0 > host1-sd: label.c:753-0 Leave write_session_label Block=4018546675d File=0d > host1-sd: append.c:300-0 back from write_end_session_label() > host1-sd: acquire.c:487-0 release_device device "DVD Writer" (/dev/dvd) is > disk > host1-sd: acquire.c:509-0 There are 0 writers in release_device > host1-sd: acquire.c:511-0 dir_create_jobmedia_record. Release Job media entries created, device released, but nothing actually written. Looks like a bug to me. > host1-sd: askdir.c:402-0 >dird: CatReq Job=xyz_projects.2007-11-14_11.24.03 > CreateJobMedia FirstIndex=1 LastIndex=37939 StartFile=0 EndFile=0 > StartBlock=65122419 EndBlock=4018574699 Copy=0 Strip=0 MediaId=12 > host1-sd: dircmd.c:172-0 Conn: Hello Director host1-dir calling > host1-sd: dircmd.c:185-0 Got a DIR connection > host1-sd: jcr.c:603-0 OnEntry JobStatus=host1-sd: jcr.c:623-0 OnExit > JobStatus=C set=C > host1-sd: cram-md5.c:73-0 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 > host1-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <[EMAIL > PROTECTED]> ssl=0 > host1-sd: cram-md5.c:152-0 sending resp to challenge: E//onTFZA7+wDiIdSVBxvA > host1-sd: dircmd.c:207-0 Message channel init completed. > host1-sd: dircmd.c:214-0 <dird: cancel Job=xyz_projects.2007-11-14_11.24.03 > > host1-sd: dircmd.c:228-0 Do command: cancel > host1-sd: jcr.c:603-0 OnEntry JobStatus=A set=A > host1-sd: jcr.c:623-0 OnExit JobStatus=A set=A > host1-sd: pythonlib.c:237-0 No startup module. > host1-sd: mem_pool.c:377-0 garbage collect memory pool > host1-sd: askdir.c:409-0 <dir: 1000 OK CreateJobMedia > host1-sd: dev.c:1636-0 weof_dev > host1-sd: acquire.c:524-0 dir_update_vol_info. Release0 > host1-sd: askdir.c:339-0 Update cat VolFiles=0 > host1-sd: askdir.c:358-0 >dird: CatReq Job=xyz_projects.2007-11-14_11.24.03 > UpdateMedia VolName=BaculaDVD0002 VolJobs=2 VolFiles=0 VolBlocks=62293 > VolBytes=4018574700 VolMounts=2 VolErrors=0 VolWrites=62294 MaxVolBytes=0 > EndTime=1195000737 VolStatus=Append Slot=0 relabel=0 InChanger=0 > VolReadTime=0 VolWriteTime=24766315 VolFirstWritten=0 VolParts=1 > host1-sd: askdir.c:182-0 <dird 1000 OK VolName=BaculaDVD0002 VolJobs=2 > VolFiles=0 VolBlocks=62293 VolBytes=4018574700 VolMounts=2 VolErrors=0 > VolWrites=62294 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 > MaxVolJobs=0 MaxVolFiles=0 InChanger=0 VolReadTime=0 VolWriteTime=24766315 > EndFile=0 EndBlock=4018574699 VolParts=1 LabelType=0 MediaId=12 > > host1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=0 > Volume=BaculaDVD0002 > host1-sd: dev.c:1836-0 close_dev "DVD Writer" (/dev/dvd) > host1-sd: dev.c:1826-0 Clear volhdr vol=BaculaDVD0002 > host1-sd: acquire.c:570-0 JobId=23 broadcast wait_device_release > host1-sd: reserve.c:487-0 jid=23 free_volume BaculaDVD0002 dev="DVD Writer" > (/dev/dvd) > host1-sd: acquire.c:585-0 ===== Device "DVD Writer" (/dev/dvd) released by > JobId=23 Device released and closed and all the attributes sent to the DIR. > host1-sd: append.c:339-0 return from do_append_data() ok=0 > host1-sd: jcr.c:603-0 OnEntry JobStatus=A set=E > host1-sd: jcr.c:623-0 OnExit JobStatus=A set=E > host1-sd: jcr.c:603-0 OnEntry JobStatus=A set=T > host1-sd: jcr.c:623-0 OnExit JobStatus=A set=T > host1-sd: pythonlib.c:237-0 No startup module. > host1-sd: dircmd.c:231-0 Command run reqeusts quit > host1-sd: pythonlib.c:237-0 No startup module. > host1-sd: mem_pool.c:377-0 garbage collect memory pool > Ok... I'd suggest the following: Run a larger job (requiring more than one part file) onto an empty disk (similar to what you did above, but let's see what happens to the second, third, and so on parts). Enable ejecting and loading the DVD after writing. If no new results show up, this looks like it might be worth a bug report. Alternatively, try to contact Hydro Meteor - he should have a more intimate knowledge of Bacula and DVD than I do as he made some experience recently ;-) Arno -- Arno Lehmann IT-Service Lehmann www.its-lehmann.de ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/ _______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
