>> 04-Feb 15:02 bcopy JobId 0: Warning: vol_mgr.c:386 Could not reserve volume
>> "PPPVE3LTOCopy_0001" for append, because it will be read.
> Googling about this lead me to only two result:
I've run it under heavvy debug:
root@pppve3:~# bcopy -d999 LTO5Storage FileStorage -i PPPVE3_0004 -o
PPPVE3LTOCopy_0001
bcopy: parse_conf.c:1003-0 Enter parse_config()
bcopy: parse_conf.c:1005-0 parse_config pass 1
bcopy: lex.c:252-0 Open config file: /etc/bacula/bacula-sd.conf
[...]
bcopy: parse_conf.c:1149-0 Leave parse_config()
bcopy: sd_plugins.c:200-0 Load sd plugins
[...]
bcopy: bcopy.c:166-0 About to setup input jcr
bcopy: jcr.c:934-0 set_jcr_job_status(0, C)
bcopy: jcr.c:943-0 OnEntry JobStatus=0 newJobstatus=C
bcopy: jcr.c:954-0 Set new stat. old: 0,0 new: C,0
bcopy: jcr.c:959-0 leave setJobStatus old=0 new=C
bcopy: butil.c:256-0 Enter find_device_res
bcopy: butil.c:259-0 Compare /dev/nst0 and LTO5Storage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and LTO5Storage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and LTO5Storage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and LTO5Storage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and LTO5Storage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and LTO5Storage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and LTO5Storage
bcopy: butil.c:276-0 Compare LTO5Storage and LTO5Storage
bcopy: butil.c:292-0 Using device: "LTO5Storage" for reading.
[...]
bcopy: message.c:816-0 Enter dispatch_msg type=6 msg=bcopy JobId 0: Ready to
read from volume "PPPVE3_0004" on Tape device "LTO5Storage" (/dev/nst0).
bcopy: message.c:1041-0 STDOUT for following msg: bcopy JobId 0: Ready to read
from volume "PPPVE3_0004" on Tape device "LTO5Storage" (/dev/nst0). 10-Feb
15:18 bcopy JobId 0: Ready to read from volume "PPPVE3_0004" on Tape device
"LTO5Storage" (/dev/nst0).
bcopy: lock.c:157-0 Lock LTO5Storage from acquire.c:339 precnt=0
bcopy: lock.c:421-0 Unblocked LTO5Storage BST_DOING_ACQUIRE from lock.c:142
bcopy: lock.c:167-0 Unlock LTO5Storage from lock.c:143 postcnt=0
bcopy: acquire.c:354-0 dcr=55824a993068 dev=55824a992408
bcopy: acquire.c:355-0 MediaType dcr= dev=LTO
bcopy: lock.c:294-0 Unlock_read_acquire from acquire.c:356
bcopy: acquire.c:357-0 Leave: bool acquire_device_for_read(DCR*)
[...]
bcopy: bcopy.c:178-0 About to setup output jcr
bcopy: jcr.c:934-0 set_jcr_job_status(0, C)
bcopy: jcr.c:943-0 OnEntry JobStatus=0 newJobstatus=C
bcopy: jcr.c:954-0 Set new stat. old: 0,0 new: C,0
bcopy: jcr.c:959-0 leave setJobStatus old=0 new=C
bcopy: butil.c:256-0 Enter find_device_res
bcopy: butil.c:259-0 Compare /dev/nst0 and FileStorage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and FileStorage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and FileStorage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and FileStorage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and FileStorage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and FileStorage
bcopy: butil.c:259-0 Compare /rpool-backup/bacula and FileStorage
bcopy: butil.c:276-0 Compare LTO5Storage and FileStorage
bcopy: butil.c:276-0 Compare FileStorage and FileStorage
bcopy: butil.c:290-0 Using device: "FileStorage" for writing.
bcopy: sd_plugins.c:156-0 No b_plugin_list: generate_global_plugin_event
ignored.
bcopy: init_dev.c:116-0 init_dev dev_type=0
bcopy: init_dev.c:152-0 Num drivers=15
bcopy: init_dev.c:165-0 loadable=0 type=1 loaded=1 name=file handle=0
bcopy: init_dev.c:252-0 Allocate dev="FileStorage" (/rpool-backup/bacula)
bcopy: init_dev.c:391-0 init_dev: tape=0 dev_name=/rpool-backup/bacula
bcopy: block_util.c:167-0 Rechdr len=64512 max_items=3225
bcopy: block_util.c:286-0 empty_block: adata=0 len=64512 set binbuf=24
bcopy: block_util.c:170-0 New block adata=0 len=64512 block=55824a99b840
bcopy: acquire.c:663-0 Attach 0x4a99b228 to dev "FileStorage"
(/rpool-backup/bacula)
bcopy: acquire.c:709-0 JobId=0 enter attach_dcr_to_dev
bcopy: acquire.c:714-0 Attach Jid=0 dcr=55824a99b228 size=0 dev="FileStorage"
(/rpool-backup/bacula)
bcopy: vol_mgr.c:152-0 add read_vol=PPPVE3LTOCopy_0001 JobId=0
bcopy: device.c:304-0 start open_output_device()
bcopy: lock.c:213-0 Enter rLock blked=BST_NOT_BLOCKED from device.c:309
bcopy: lock.c:217-0 Lock FileStorage in rLock BST_NOT_BLOCKED from device.c:309
bcopy: device.c:313-0 Device is file, deferring open.
bcopy: lock.c:173-0 rUnlock from device.c:326
bcopy: lock.c:167-0 Unlock FileStorage from device.c:326 postcnt=0
bcopy: bcopy.c:187-0 About to acquire device for writing
bcopy: lock.c:213-0 Enter rLock blked=BST_NOT_BLOCKED from bcopy.c:189
bcopy: lock.c:217-0 Lock FileStorage in rLock BST_NOT_BLOCKED from bcopy.c:189
bcopy: file_dev.c:138-0 Enter: virtual bool file_dev::open_device(DCR*, int)
bcopy: dev.c:113-0 Enter: virtual bool DEVICE::open_device(DCR*, int)
bcopy: dev.c:325-0 Enter: virtual bool DEVICE::mount(int)
bcopy: file_dev.c:184-0 open disk: mode=OPEN_READ_WRITE
open(/rpool-backup/bacula/PPPVE3LTOCopy_0001, 0x2, 0640)
bcopy: file_dev.c:194-0 Did
open(/rpool-backup/bacula/PPPVE3LTOCopy_0001,OPEN_READ_WRITE,0640)
bcopy: file_dev.c:211-0 open dev: disk fd=4 opened
bcopy: file_dev.c:214-0 Leave: virtual bool file_dev::open_device(DCR*, int)
bcopy: lock.c:167-0 Unlock FileStorage from bcopy.c:195 postcnt=0
bcopy: acquire.c:377-0 Enter: DCR* acquire_device_for_append(DCR*)
bcopy: lock.c:276-0 Lock_acquire from acquire.c:381
bcopy: lock.c:157-0 Lock FileStorage from acquire.c:382 precnt=0
bcopy: acquire.c:383-0 acquire_append device is File
bcopy: lock.c:213-0 Enter rLock blked=BST_NOT_BLOCKED from acquire.c:416
bcopy: lock.c:410-0 Blocked FileStorage BST_DOING_ACQUIRE from acquire.c:417
bcopy: lock.c:167-0 Unlock FileStorage from acquire.c:418 postcnt=0
bcopy: acquire.c:419-0 jid=0 Do mount_next_write_vol
bcopy: mount.c:73-0 Enter: bool DCR::mount_next_write_volume()
bcopy: mount.c:76-0 Enter mount_next_volume(release=0) dev="FileStorage"
(/rpool-backup/bacula)
bcopy: mount.c:88-0 mount_next_vol retry=0
bcopy: mount.c:636-0 No swap_dev set. dev->vol=0
bcopy: mount.c:361-0 Before dir_find_next_appendable_volume.
bcopy: askdir.c:172-0 Fake dir_get_volume_info
bcopy: askdir.c:174-0 Vol=PPPVE3LTOCopy_0001 VolType=0
bcopy: mount.c:123-0 After find_a_volume. Vol=PPPVE3LTOCopy_0001 Slot=0
VolType=0
bcopy: dev.c:506-0 Notify dcrs of vol change. oldVolume=PPPVE3LTOCopy_0001
NewVolume=PPPVE3LTOCopy_0001
bcopy: autochanger.c:105-0 Device "FileStorage" (/rpool-backup/bacula) is not
an autochanger
bcopy: mount.c:151-0 autoload_dev returns 0
bcopy: mount.c:164-0 (2)Ask=0
bcopy: mount.c:167-0 Ask=0 autochanger=0
bcopy: mount.c:182-0 want vol=PPPVE3LTOCopy_0001 devvol= dev="FileStorage"
(/rpool-backup/bacula)
bcopy: mount.c:190-0 Try open Vol=PPPVE3LTOCopy_0001
bcopy: file_dev.c:138-0 Enter: virtual bool file_dev::open_device(DCR*, int)
bcopy: dev.c:113-0 Enter: virtual bool DEVICE::open_device(DCR*, int)
bcopy: file_dev.c:140-0 Leave: virtual bool file_dev::open_device(DCR*, int)
bcopy: file_dev.c:138-0 Enter: virtual bool file_dev::open_device(DCR*, int)
bcopy: dev.c:113-0 Enter: virtual bool DEVICE::open_device(DCR*, int)
bcopy: file_dev.c:140-0 Leave: virtual bool file_dev::open_device(DCR*, int)
bcopy: mount.c:399-0 Enter: int DCR::check_volume_label(bool&, bool&)
bcopy: label.c:72-0 Enter: virtual int DEVICE::read_dev_volume_label(DCR*)
bcopy: label.c:75-0 Enter read_volume_label adata=0 res=0 device="FileStorage"
(/rpool-backup/bacula) vol=PPPVE3LTOCopy_0001 dev_Vol=*NULL*
bcopy: label.c:90-0 ==== worm=0 ====
bcopy: file_dev.c:71-0 Enter: virtual bool DEVICE::rewind(DCR*)
bcopy: file_dev.c:72-0 rewind res=0 fd=4 "FileStorage" (/rpool-backup/bacula)
bcopy: block_util.c:286-0 empty_block: adata=0 len=64512 set binbuf=24
bcopy: label.c:129-0 Big if statement in read_volume_label
bcopy: block.c:520-0 Pos for read=0 0
bcopy: block.c:545-0 Read() adata=0 vol= nbytes=245 pos=0
bcopy: block_util.c:448-0 unser_block_header block_len=245
bcopy: block_util.c:456-0 set block=55824a99b840 adata=0 binbuf=221
bcopy: block_util.c:460-0 Read binbuf = 221 24 block_len=245
bcopy: block.c:641-0 adata=0 block_len=245 buf_len=64512
bcopy: block.c:734-0 At end of read block
bcopy: block.c:748-0 Exit read_block read_len=245 block_len=245 binbuf=221
bcopy: block_util.c:105-0 Dump block st_none 55824a99b840: adata=0 size=245
BlkNum=0
Hdrcksum=e22956af cksum=e22956af
bcopy: record_read.c:211-0 Rdata full adata=0 FI=PRE_LABEL SessId=0 Strm=0
len=209 block=55824a99b840
bcopy: label.c:982-0 Enter: bool unser_volume_label(DEVICE*, DEV_RECORD*)
bcopy: label.c:999-0 reclen=209 recdata=Bacula 1.0 immortal
bcopy: label.c:1001-0 reclen=209 recdata=Bacula 1.0 immortal
bcopy: label.c:1035-0 unser_vol_label
Volume Label:
Adata : 0
Id : Bacula 1.0 immortal
VerNo : 11
VolName : PPPVE3LTOCopy_0001
PrevVolName :
VolFile : 0
LabelType : PRE_LABEL
LabelSize : 209
PoolName : FVG-PP-PPPVE3LTOCopyPool
MediaType : File
PoolType : Backup
HostName : pppve3
Date label written: 04-Feb-2025 14:25
bcopy: label.c:1039-0 Leave: bool unser_volume_label(DEVICE*, DEV_RECORD*)
bcopy: label.c:152-0 VolHdr.Id OK: Bacula 1.0 immortal
bcopy: record_util.c:277-0 Enter free_record.
bcopy: record_util.c:281-0 Data buf is freed.
bcopy: record_util.c:283-0 Leave free_record.
bcopy: label.c:191-0 VolHdr.VerNum=11 OK.
bcopy: label.c:211-0 Compare Vol names: VolName=PPPVE3LTOCopy_0001
hdr=PPPVE3LTOCopy_0001
Volume Label:
Adata : 0
Id : Bacula 1.0 immortal
VerNo : 11
VolName : PPPVE3LTOCopy_0001
PrevVolName :
VolFile : 0
LabelType : PRE_LABEL
LabelSize : 209
PoolName : FVG-PP-PPPVE3LTOCopyPool
MediaType : File
PoolType : Backup
HostName : pppve3
Date label written: 04-Feb-2025 14:25
bcopy: label.c:261-0 Leave read_volume_label() VOL_OK
bcopy: file_dev.c:71-0 Enter: virtual bool DEVICE::rewind(DCR*)
bcopy: file_dev.c:72-0 rewind res=0 fd=4 "FileStorage" (/rpool-backup/bacula)
bcopy: label.c:274-0 Call reserve_volume=PPPVE3LTOCopy_0001
bcopy: vol_mgr.c:381-0 enter reserve_volume=PPPVE3LTOCopy_0001
drive="FileStorage" (/rpool-backup/bacula)
bcopy: label.c:280-0 Could not reserve volume PPPVE3LTOCopy_0001 on
"FileStorage" (/rpool-backup/bacula)
bcopy: block_util.c:286-0 empty_block: adata=0 len=64512 set binbuf=24
bcopy: file_dev.c:71-0 Enter: virtual bool DEVICE::rewind(DCR*)
bcopy: file_dev.c:72-0 rewind res=0 fd=4 "FileStorage" (/rpool-backup/bacula)
bcopy: label.c:295-0 return stat=5 vol_mgr.c:386 Could not reserve volume
"PPPVE3LTOCopy_0001" for append, because it will be read.
bcopy: label.c:296-0 Leave: virtual int DEVICE::read_dev_volume_label(DCR*)
bcopy: mount.c:418-0 Want dirVol=PPPVE3LTOCopy_0001 dirStat=
bcopy: mount.c:433-0 Vol NAME Error Have=PPPVE3LTOCopy_0001,
want=PPPVE3LTOCopy_0001
bcopy: askdir.c:172-0 Fake dir_get_volume_info
bcopy: askdir.c:174-0 Vol=PPPVE3LTOCopy_0001 VolType=0
bcopy: mount.c:493-0 Got new Volume name=PPPVE3LTOCopy_0001
bcopy: mount.c:495-0 Call reserve_volume=PPPVE3LTOCopy_0001
bcopy: vol_mgr.c:381-0 enter reserve_volume=PPPVE3LTOCopy_0001
drive="FileStorage" (/rpool-backup/bacula)
bcopy: message.c:1455-0 Enter Jmsg type=5
bcopy: message.c:816-0 Enter dispatch_msg type=5 msg=bcopy JobId 0: Warning:
vol_mgr.c:386 Could not reserve volume "PPPVE3LTOCopy_0001" for append, because
it will be read.
bcopy: message.c:1041-0 STDOUT for following msg: bcopy JobId 0: Warning:
vol_mgr.c:386 Could not reserve volume "PPPVE3LTOCopy_0001" for append, because
it will be read.
10-Feb 15:18 bcopy JobId 0: Warning: vol_mgr.c:386 Could not reserve volume
"PPPVE3LTOCopy_0001" for append, because it will be read.
bcopy: mount.c:548-0 Leave: int DCR::check_volume_label(bool&, bool&)
bcopy: mount.c:246-0 set_unload
If i understand well the code and the debug, in 'label.c' the volume get
opened to read the label, and succeded; after that the volume get reopened
to be 'reserved', and this lead to the infamous error 'Could not reserve volume
... for append, because it will be read'.
Looking at code lead me to vol_mgr.c, row 383:
https://gitlab.bacula.org/bacula-community-edition/bacula-community/-/blob/Branch-9.4/bacula/src/stored/vol_mgr.c?ref_type=heads#L383
and if i've understood well the code check if the volume is in a read list,
but this info is probably available only if the check get done by a
director (or an SD), not by bcopy standalone program.
Seems to me a very similar bug to:
https://bugs.bacula.org/view.php?id=2122
but my C and bacula knowledge is minimal...
Thanks.
--
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
