Hello,
On 1/11/2006 1:44 PM, Andrew Couchman wrote:
Hi,
I've been setting up a system to use Bacula for a few weeks now and
I'm having problems with the DVD burning part. I've been following
various threads and had arrived at the point of bacula stopping while
waiting for the resource for ever. However after updating to 1.38.4 I
got a lot further. In fact doing a back-up of about 4GB of data, the
first chunk of 800Mb or so got written to DVD. Then the second 800Mb
was read from the file demon and stored on the server ready for burning
as /tmp/backup/20060111-test.1 - however when it came to time to write
this second chunk something went wrong. I can't really claim to
understand all the output but the part that looks strange to me is the
reference to /dev/fd/3 - all my config files reference /dev/dvd or
/mnt/cdrom and my system doesn't even have a /dev/fd - so I can
understand that this would cause a problem, but not why it is trying to
access this in the first place.
Well, most probably you do have /dev/fd/* in your system - that's the
(more or less virtual) collection of *F*ile *D*escriptors, uniqe for
each process.
Any help gratefully appreciated!
The first idea I have is that another process is usingthe DVD.
That's something I really hate with modern distributions - all the
automatic mounting and program starting. Just as an example:
Here, whenever the automounting stuff detected a DVD with data on it, it
was automatically mounted. Subsequent tries by the SD to mount it then
failed. The solution to this was to modify the /etc/fstab line referring
to that device, i.e. remove subfs and simply set up manual mounting.
HAL, DBus, autofs etc. are some other problem technologies that come to
my mind, but I'm afraid that there will surely be more, most probably
poorly documented.
At a customer, who runs a complete graphical desktop (KDE in this case)
on his file server (urgh...) and usually remained logged in (urgh^2) as
root user (shake head...) whenever you insert an empty DVD K3B is
started and uses the drive. As a result growisofs claimed to run without
errors, but nothing was actually written to disk. I had to modify some
arcane settings file which, of course, was totally undocumented.
You might run into similar problems.
One idea to solve this is to ask your OS distributor (or, more
successful IMO, ask the users mailing list) how to disable that sort of
stuff. Additionally, I considered a routine in my dvd-handler script
that would use lsof to find any processes using the device in question
and kill -9'ing them before anything was done with the drive.
The better solution is to trim down your distribution to not do such
stuff, but that might be nearly impossible considering the amount of
software packages that get installed, the dependencies the package
maintainers claim there are, and the usually non-existing documentation
concerning these technologies.
Below is all the info I could think of supplying:
...
let's see...
...
And finally here is the debug output from the storage demon when it failed:
...
backup-sd: dev.c:277 open dev: tape=0 dev_name="DVD-Writer" (/dev/dvd)
vol=20060111-test mode=OPEN_READ_WRITE
backup-sd: dev.c:283 call open_dvd_device mode=OPEN_READ_WRITE
backup-sd: dev.c:470 Enter: open_dvd_dev: DVD dev= mode=OPEN_READ_WRITE
backup-sd: dev.c:487 open_dvd_device: num_parts=0, VolCatInfo.VolCatParts=0
backup-sd: dvd.c:78 Enter mount_dev
backup-sd: dvd.c:152 Device "DVD-Writer" (/dev/dvd) cannot be mounted.
ERR=mount: wrong fs type, bad option, bad superblock on /dev/dvd,
or too many mounted file systems
backup-sd: dvd.c:196 open_mounted_dev: got 0 files in the mount point
(not counting ., .. and .keep)
backup-sd: dvd.c:78 Enter mount_dev
backup-sd: dvd.c:152 Device "DVD-Writer" (/dev/dvd) cannot be mounted.
ERR=mount: wrong fs type, bad option, bad superblock on /dev/dvd,
or too many mounted file systems
backup-sd: dvd.c:196 open_mounted_dev: got 0 files in the mount point
(not counting ., .. and .keep)
backup-sd: dvd.c:248 update_free_space_dev: cmd=/etc/bacula/dvd-handler
/dev/dvd free
backup-sd: dvd.c:257 Free space program run : 4695588864
No Error reported.
backup-sd: dvd.c:292 update_free_space_dev: free_space=4695588864
freespace_ok=1 free_space_errno=0 have_media=1
backup-sd: dev.c:514 Could not mount device "DVD-Writer" (/dev/dvd),
this is not a problem (num_parts == 0), and have media.
backup-sd: dev.c:533 open dev: DVD dev= mode=OPEN_READ_WRITE part=0
npart=0 volcatnparts=0
backup-sd: dev.c:535 openmode=2 OPEN_READ_WRITE
backup-sd: dvd.c:69 Exit make_dvd_filename: arch=/tmp/backup/20060111-test
backup-sd: dev.c:552 mode=OPEN_READ_WRITE
open(/tmp/backup/20060111-test, 0x42, 0640)
backup-sd: dev.c:576 after open fd=7
backup-sd: dvd.c:559 Enter lseek_dev fd=7 part=0 nparts=0
backup-sd: dvd.c:601 lseek_dev SEEK_CUR to 0
backup-sd: dvd.c:607 lseek_dev SEEK_CUR returns 0
backup-sd: label.c:71 Enter read_volume_label res=1 device="DVD-Writer"
(/dev/dvd) vol=20060111-test dev_Vol=*NULL*
backup-sd: dev.c:621 rewind res=1 fd=7 "DVD-Writer" (/dev/dvd)
backup-sd: dvd.c:559 Enter lseek_dev fd=7 part=0 nparts=0
backup-sd: dvd.c:569 lseek_dev SEEK_SET to 0 (part_start=0)
backup-sd: label.c:138 Big if statement in read_volume_label
backup-sd: label.c:143 Requested Volume "20060111-test" on "DVD-Writer"
(/dev/dvd) is not a Bacula labeled Volume, because: ERR=block.c:953 Read
zero bytes at 0:0 on device "DVD-Writer" (/dev/dvd).
Ok, this looks ok up up to here. Basically, the SD finds an empty disk.
backup-sd: dev.c:621 rewind res=1 fd=7 "DVD-Writer" (/dev/dvd)
backup-sd: dvd.c:559 Enter lseek_dev fd=7 part=0 nparts=0
backup-sd: dvd.c:569 lseek_dev SEEK_SET to 0 (part_start=0)
backup-sd: label.c:299 write_volume_label()
backup-sd: dev.c:621 rewind res=1 fd=7 "DVD-Writer" (/dev/dvd)
backup-sd: dvd.c:559 Enter lseek_dev fd=7 part=0 nparts=0
backup-sd: dvd.c:569 lseek_dev SEEK_SET to 0 (part_start=0)
backup-sd: label.c:538 Start create_volume_label()
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : 20060111-test
PrevVolName :
VolFile : 0
LabelType : PRE_LABEL
LabelSize : 0
PoolName : Default
MediaType : DVD
PoolType : Backup
HostName : pc-00001.andrewcouchman.co.uk
Date label written: 11-Jan-2006 11:13
backup-sd: label.c:341 Wrote label of 191 bytes to "DVD-Writer" (/dev/dvd)
backup-sd: label.c:344 Call write_block_to_dev()
backup-sd: label.c:349 Wrote block to device
backup-sd: dev.c:1504 weof_dev
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : 20060111-test
PrevVolName :
VolFile : 0
LabelType : PRE_LABEL
LabelSize : 0
PoolName : Default
MediaType : DVD
PoolType : Backup
HostName : pc-00001.andrewcouchman.co.uk
Date label written: 11-Jan-2006 11:13
backup-sd: device.c:322 Force close_dev "DVD-Writer" (/dev/dvd)
backup-sd: dev.c:1685 really close_dev "DVD-Writer" (/dev/dvd)
Here, unfortunately, I'm not sure any more... This looks like the label
was written to DVD, although, IMO, it should still remain in the part
file on disk. That's something I would have to verify in the source
code, basically checking if device.c actually writes to DVD when it says
so or if it's still using the part file.
backup-sd: dvd.c:93 Enter unmount_dev
backup-sd: dircmd.c:513 Found device DVD-Writer
backup-sd: dircmd.c:551 Found changer device DVD-Writer
backup-sd: dircmd.c:576 mount cmd blocked=2
backup-sd: dircmd.c:580 Waiting for mount. Attempting to wake thread
This is unecpected. Right after labeling a volume, there should be no
need to call the operator to mount the volume.
backup-sd: askdir.c:451 Back from wait_for_sysop stat=4
backup-sd: askdir.c:473 Someone woke me for device "DVD-Writer" (/dev/dvd)
backup-sd: askdir.c:242 >dird: CatReq
Job=Andrews_laptop_DVD.2006-01-11_11.12.34 FindMedia=1 pool_name=Default
media_type=DVD
backup-sd: askdir.c:165 <dird 1000 OK VolName=20060111-test VolJobs=0
VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=0 VolErrors=0 VolWrites=0
MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=0
MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0 EndFile=0
EndBlock=0 VolParts=0 LabelType=0
backup-sd: askdir.c:242 >dird: CatReq
Job=Andrews_laptop_DVD.2006-01-11_11.12.34 FindMedia=1 pool_name=Default
media_type=DVD
backup-sd: askdir.c:165 <dird 1000 OK VolName=20060111-test VolJobs=0
VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=0 VolErrors=0 VolWrites=0
MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=0
MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0 EndFile=0
EndBlock=0 VolParts=0 LabelType=0
backup-sd: dev.c:277 open dev: tape=0 dev_name="DVD-Writer" (/dev/dvd)
vol=20060111-test mode=OPEN_READ_WRITE
backup-sd: dev.c:283 call open_dvd_device mode=OPEN_READ_WRITE
backup-sd: dev.c:470 Enter: open_dvd_dev: DVD dev= mode=OPEN_READ_WRITE
backup-sd: dev.c:487 open_dvd_device: num_parts=0, VolCatInfo.VolCatParts=0
backup-sd: dvd.c:78 Enter mount_dev
backup-sd: dvd.c:152 Device "DVD-Writer" (/dev/dvd) cannot be mounted.
ERR=mount: wrong fs type, bad option, bad superblock on /dev/dvd,
or too many mounted file systems
backup-sd: dvd.c:196 open_mounted_dev: got 0 files in the mount point
(not counting ., .. and .keep)
backup-sd: dvd.c:78 Enter mount_dev
backup-sd: dvd.c:152 Device "DVD-Writer" (/dev/dvd) cannot be mounted.
ERR=mount: wrong fs type, bad option, bad superblock on /dev/dvd,
or too many mounted file systems
backup-sd: dvd.c:196 open_mounted_dev: got 0 files in the mount point
(not counting ., .. and .keep)
backup-sd: dvd.c:248 update_free_space_dev: cmd=/etc/bacula/dvd-handler
/dev/dvd free
backup-sd: dvd.c:257 Free space program run : 4695588864
No Error reported.
backup-sd: dvd.c:292 update_free_space_dev: free_space=4695588864
freespace_ok=1 free_space_errno=0 have_media=1
backup-sd: dev.c:514 Could not mount device "DVD-Writer" (/dev/dvd),
this is not a problem (num_parts == 0), and have media.
backup-sd: dev.c:533 open dev: DVD dev= mode=OPEN_READ_WRITE part=0
npart=0 volcatnparts=0
backup-sd: dev.c:535 openmode=2 OPEN_READ_WRITE
backup-sd: dvd.c:69 Exit make_dvd_filename: arch=/tmp/backup/20060111-test
backup-sd: dev.c:552 mode=OPEN_READ_WRITE
open(/tmp/backup/20060111-test, 0x42, 0640)
backup-sd: dev.c:576 after open fd=6
backup-sd: dvd.c:559 Enter lseek_dev fd=6 part=0 nparts=0
backup-sd: dvd.c:601 lseek_dev SEEK_CUR to 0
backup-sd: dvd.c:607 lseek_dev SEEK_CUR returns 0
backup-sd: label.c:71 Enter read_volume_label res=1 device="DVD-Writer"
(/dev/dvd) vol=20060111-test dev_Vol=*NULL*
backup-sd: dev.c:621 rewind res=1 fd=6 "DVD-Writer" (/dev/dvd)
backup-sd: dvd.c:559 Enter lseek_dev fd=6 part=0 nparts=0
backup-sd: dvd.c:569 lseek_dev SEEK_SET to 0 (part_start=0)
backup-sd: label.c:138 Big if statement in read_volume_label
backup-sd: label.c:206 Compare Vol names: VolName=20060111-test
hdr=20060111-test
backup-sd: label.c:222 Copy vol_name=20060111-test
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : 20060111-test
PrevVolName :
VolFile : 0
LabelType : PRE_LABEL
LabelSize : 191
PoolName : Default
MediaType : DVD
PoolType : Backup
HostName : pc-00001.andrewcouchman.co.uk
Date label written: 11-Jan-2006 11:13
backup-sd: label.c:227 Leave read_volume_label() VOL_OK
backup-sd: dev.c:621 rewind res=1 fd=6 "DVD-Writer" (/dev/dvd)
backup-sd: dvd.c:559 Enter lseek_dev fd=6 part=0 nparts=0
backup-sd: dvd.c:569 lseek_dev SEEK_SET to 0 (part_start=0)
backup-sd: label.c:262 write Label in write_volume_label_to_block()
backup-sd: label.c:276 Wrote label of 191 bytes to block
This looks ok, though - Bacula verified the volume label.
backup-sd: dev.c:621 rewind res=1 fd=6 "DVD-Writer" (/dev/dvd)
backup-sd: dvd.c:559 Enter lseek_dev fd=6 part=0 nparts=0
backup-sd: dvd.c:569 lseek_dev SEEK_SET to 0 (part_start=0)
backup-sd: askdir.c:294 Update cat VolFiles=0
backup-sd: askdir.c:313 >dird: CatReq
Job=Andrews_laptop_DVD.2006-01-11_11.12.34 UpdateMedia
VolName=20060111-test VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1
VolMounts=1 VolErrors=0 VolWrites=1 MaxVolBytes=0 EndTime=1136977997
VolStatus=Append Slot=0 relabel=1 InChanger=1 VolReadTime=0
VolWriteTime=0 VolParts=0
backup-sd: askdir.c:165 <dird 1000 OK VolName=20060111-test VolJobs=0
VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=1 VolErrors=0 VolWrites=1
MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0 MaxVolJobs=0
MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0 EndFile=0
EndBlock=0 VolParts=0 LabelType=0
backup-sd: acquire.c:394 Dec reserve=0
backup-sd: append.c:81 Begin append device="DVD-Writer" (/dev/dvd)
backup-sd: append.c:86 Just after acquire_device_for_append
backup-sd: label.c:636 session_label record=80aa660
backup-sd: label.c:692 Write sesson_label record JobId=54 FI=SOS_LABEL
SessId=1 Strm=54 len=189 remainder=0
backup-sd: label.c:696 Leave write_session_label Block=226 File=0
backup-sd: dvd.c:411 Enter: ==== open_next_part part=0 npart=0
dev="DVD-Writer" (/dev/dvd) vol=20060111-test mode=2 file_addr=838849690
backup-sd: dvd.c:342 dvd_write_part: device is "DVD-Writer" (/dev/dvd),
part is 0, is_mounted=0
backup-sd: dvd.c:69 Exit make_dvd_filename: arch=/tmp/backup/20060111-test
backup-sd: dvd.c:370 dvd_write_part: cmd=/etc/bacula/dvd-handler
/dev/dvd write 1 /tmp/backup/20060111-test timeout=16000
backup-sd: dvd.c:69 Exit make_dvd_filename: arch=/tmp/backup/20060111-test
backup-sd: dvd.c:388 unlink(/tmp/backup/20060111-test)
backup-sd: dvd.c:78 Enter mount_dev
backup-sd: dvd.c:78 Enter mount_dev
backup-sd: dvd.c:248 update_free_space_dev: cmd=/etc/bacula/dvd-handler
/dev/dvd free
backup-sd: dvd.c:257 Free space program run : 3856367616
No Error reported.
Everythink is ok, dspite my worries from above - the first part file was
successfully written to disk. Good.
backup-sd: dvd.c:292 update_free_space_dev: free_space=3856367616
freespace_ok=1 free_space_errno=0 have_media=1
backup-sd: dvd.c:449 part=1 num_parts=1
backup-sd: dvd.c:500 Call dev->open(vol=20060111-test, mode=2
backup-sd: dev.c:277 open dev: tape=0 dev_name="DVD-Writer" (/dev/dvd)
vol=20060111-test mode=OPEN_READ_WRITE
backup-sd: dev.c:283 call open_dvd_device mode=OPEN_READ_WRITE
backup-sd: dev.c:470 Enter: open_dvd_dev: DVD dev= mode=OPEN_READ_WRITE
backup-sd: dev.c:487 open_dvd_device: num_parts=1, VolCatInfo.VolCatParts=0
backup-sd: dvd.c:78 Enter mount_dev
backup-sd: dev.c:533 open dev: DVD dev= mode=OPEN_READ_WRITE part=1
npart=1 volcatnparts=0
backup-sd: dev.c:535 openmode=2 OPEN_READ_WRITE
backup-sd: dvd.c:69 Exit make_dvd_filename:
arch=/tmp/backup/20060111-test.1
backup-sd: dev.c:552 mode=OPEN_READ_WRITE
open(/tmp/backup/20060111-test.1, 0x42, 0640)
backup-sd: dev.c:576 after open fd=6
backup-sd: dvd.c:559 Enter lseek_dev fd=6 part=1 nparts=1
backup-sd: dvd.c:601 lseek_dev SEEK_CUR to 0
backup-sd: dvd.c:607 lseek_dev SEEK_CUR returns 838849917
backup-sd: askdir.c:294 Update cat VolFiles=0
backup-sd: askdir.c:313 >dird: CatReq
Job=Andrews_laptop_DVD.2006-01-11_11.12.34 UpdateMedia
VolName=20060111-test VolJobs=0 VolFiles=0 VolBlocks=13003
VolBytes=838849464 VolMounts=1 VolErrors=0 VolWrites=13004 MaxVolBytes=0
EndTime=1136979013 VolStatus=Append Slot=0 relabel=0 InChanger=1
VolReadTime=0 VolWriteTime=0 VolParts=1
backup-sd: askdir.c:165 <dird 1000 OK VolName=20060111-test VolJobs=0
VolFiles=0 VolBlocks=13003 VolBytes=838849464 VolMounts=1 VolErrors=0
VolWrites=13004 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0
MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0
EndFile=0 EndBlock=0 VolParts=1 LabelType=0
backup-sd: dev.c:1504 weof_dev
backup-sd: askdir.c:346 >dird: CatReq
Job=Andrews_laptop_DVD.2006-01-11_11.12.34 CreateJobMedia FirstIndex=1
LastIndex=15540 StartFile=0 EndFile=0 StartBlock=227 EndBlock=999936362
Copy=0 Strip=0
backup-sd: askdir.c:353 <dir: 1000 OK CreateJobMedia
backup-sd: askdir.c:294 Update cat VolFiles=0
backup-sd: askdir.c:313 >dird: CatReq
Job=Andrews_laptop_DVD.2006-01-11_11.12.34 UpdateMedia
VolName=20060111-test VolJobs=0 VolFiles=0 VolBlocks=15500
VolBytes=999935910 VolMounts=1 VolErrors=0 VolWrites=15501 MaxVolBytes=0
EndTime=1136979161 VolStatus=Append Slot=0 relabel=0 InChanger=1
VolReadTime=0 VolWriteTime=0 VolParts=1
backup-sd: askdir.c:165 <dird 1000 OK VolName=20060111-test VolJobs=0
VolFiles=0 VolBlocks=15500 VolBytes=999935910 VolMounts=1 VolErrors=0
VolWrites=15501 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append Slot=0
MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0
EndFile=0 EndBlock=999936362 VolParts=1 LabelType=0
backup-sd: block.c:759 dir_update_volume_info max file size -- OK
backup-sd: dvd.c:411 Enter: ==== open_next_part part=1 npart=1
dev="DVD-Writer" (/dev/dvd) vol=20060111-test mode=2 file_addr=1677699402
backup-sd: dvd.c:342 dvd_write_part: device is "DVD-Writer" (/dev/dvd),
part is 1, is_mounted=32768
backup-sd: dvd.c:69 Exit make_dvd_filename:
arch=/tmp/backup/20060111-test.1
backup-sd: dvd.c:370 dvd_write_part: cmd=/etc/bacula/dvd-handler
/dev/dvd write 0 /tmp/backup/20060111-test.1 timeout=2727
Now it's getting really interesting.
backup-sd: dvd.c:376 dvd.c:375 Error while writing current part to the
DVD: Running /usr/bin/growisofs -use-the-force-luke=notray -quiet
-use-the-force-luke=4gms -A 'Bacula Data' -input-charset=default
-iso-level 3 -pad -p 'dvd-handler / growisofs' -sysid 'BACULADATA' -R -M
/dev/dvd /tmp/backup/20060111-test.1
Executing 'mkisofs -quiet -A Bacula Data -input-charset=default
-iso-level 3 -pad -p dvd-handler / growisofs -sysid BACULADATA -R -C
16,409776 -M /dev/fd/3 /tmp/backup/20060111-test.1 | builtin_dd
of=/dev/dvd obs=32k seek=25611'
mkisofs: No such file or directory. Cannot open '/dev/fd/3'. Cannot open
SCSI driver.
Ok, I see your problem.
AFAIK, the part of the mkisofs command line reading of=/dev/dvd is
generated by growisofs and is usually right. mkisofs can't use /dev/dvd,
though. So, I suspect that, for some reason, that device is not
available or mkisofs doesn't have the necessary permissions to use it.
This might be because the device is already in use by another process,
which you could check using lsof for example.
I'd try to change the configuration: exchange the archive device
/dev/dvd in your SD conf with the real hardware device, probably
something like /dev/hdc or similar. Try to avoid the
distribution-supplied symbolic links.
The remaining part of the debug output is more or less only error
processing through the different layers of the software.
Try to clean up your system so that nothing automatically happens with
your DVD writer, and try to find if you see any reason why mkisofs isn't
allowed to access the device it needs,I'd suggest.
Hope this helps,
Arno
--
IT-Service Lehmann [EMAIL PROTECTED]
Arno Lehmann http://www.its-lehmann.de
-------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc. Do you grep through log files
for problems? Stop! Download the new AJAX search engine that makes
searching your log files as easy as surfing the web. DOWNLOAD SPLUNK!
http://ads.osdn.com/?ad_id=7637&alloc_id=16865&op=click
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
