First let me apologize if this email is too large. I've included a
lot of debug messages to illustrate and maybe someone can spot the
obvious that I can't. I've upgraded to bacula 1.38-2 and can't seem
to get it to work with my tape changer (1.36 did work). I added the -
d 400 to the storage daemon start up and generated some of the
following messages. When I restart Bacula I get the following:
<From here >
[EMAIL PROTECTED] bacula]# ./bacula restart
Stopping the Bacula File daemon
Stopping the Bacula Storage daemon
Stopping the Bacula Director daemon
Starting the Bacula Storage daemon
bacula-sd: lex.c:148 Open config file: /etc/bacula/bacula-sd.conf
bacula-sd: stored_conf.c:613 Inserting director res: rosalind-mon
bacula-sd: stored_conf.c:613 Inserting device res: GeneSplicer
bacula-sd: lex.c:148 Open config file: /etc/bacula/bacula-sd.conf
bacula-sd: message.c:238 Copy message resource 0x80a7148 to 0x80a5cc0
Starting the Bacula File daemon
rosalind-sd: jcr.c:113 read_last_jobs seek to 188
rosalind-sd: jcr.c:120 Read num_items=10
rosalind-sd: bpipe.c:291 Run program returning 0
rosalind-sd: bnet_server.c:83 Addresses host[ipv4:0.0.0.0:9103]
rosalind-sd: stored.c:451 calling init_dev /mnt/amanda
rosalind-sd: dev.c:242 init_dev: tape=0 dev_name=/mnt/amanda
rosalind-sd: stored.c:453 SD init done /mnt/amanda
rosalind-sd: stored.c:466 calling first_open_device "FileBackUp" (/
mnt/amanda)
rosalind-sd: device.c:246 start open_output_device()
rosalind-sd: device.c:255 Device is file, deferring open.
rosalind-sd: stored.c:451 calling init_dev /dev/nst0
rosalind-sd: dev.c:242 init_dev: tape=2 dev_name=/dev/nst0
rosalind-sd: stored.c:453 SD init done /dev/nst0
rosalind-sd: autochanger.c:246 Locking changer AIT3-Changer
rosalind-sd: bpipe.c:291 Run program returning 0
rosalind-sd: autochanger.c:217 run_prog: /etc/bacula/mtx-changer /dev/
sg1 loaded 0 /dev/nst0 0 stat=0 result=Doing mtx -f /dev/sg1 0 -- to
find what is loaded
rosalind-sd: autochanger.c:255 Unlocking changer AIT3-Changer
rosalind-sd: stored.c:466 calling first_open_device "GeneSplicer" (/
dev/nst0)
rosalind-sd: device.c:246 start open_output_device()
rosalind-sd: device.c:265 Opening device.
rosalind-sd: dev.c:277 open dev: tape=2 dev_name="GeneSplicer" (/dev/
nst0) vol= mode=OPEN_READ_ONLY
rosalind-sd: dev.c:335 open dev: device is tape
rosalind-sd: autochanger.c:246 Locking changer AIT3-Changer
rosalind-sd: bpipe.c:291 Run program returning 0
rosalind-sd: autochanger.c:217 run_prog: /etc/bacula/mtx-changer /dev/
sg1 loaded 0 /dev/nst0 0 stat=0 result=Doing mtx -f /dev/sg1 0 -- to
find what is loaded
rosalind-sd: autochanger.c:255 Unlocking changer AIT3-Changer
rosalind-sd: dev.c:358 Try open "GeneSplicer" (/dev/nst0)
mode=OPEN_READ_ONLY nonblocking=2048
rosalind-sd: dev.c:397 openmode=3 OPEN_READ_ONLY
rosalind-sd: dev.c:410 open dev: tape 6 opened
rosalind-sd: device.c:272 open dev "GeneSplicer" (/dev/nst0) OK
rosalind-sd: label.c:71 Enter read_volume_label
device="GeneSplicer" (/dev/nst0) vol= dev_Vol=*NULL*
rosalind-sd: dev.c:655 rewind_dev fd=6 "GeneSplicer" (/dev/nst0)
rosalind-sd: label.c:138 Big if statement in read_volume_label
rosalind-sd: block.c:884 Full read() in read_block_from_device()
len=64512
Starting the Bacula Director daemon
[EMAIL PROTECTED] bacula]# rosalind-sd: block.c:948 Read device got
64512 bytes at 0:0
rosalind-sd: block.c:285 unser_block_header block_len=221
rosalind-sd: block.c:296 Read binbuf = 197 24 block_len=221
rosalind-sd: block.c:1070 At end of read block
rosalind-sd: block.c:1083 Exit read_block read_len=64512 block_len=221
rosalind-sd: label.c:758 unser_vol_label
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : Chromosome0014
PrevVolName :
VolFile : 0
LabelType : VOL_LABEL
LabelSize : 185
PoolName : GenePool
MediaType : SDX700-C
PoolType : Backup
HostName : rosalind.partners.org
Date label written: 01-Nov-2005 14:44
rosalind-sd: reserve.c:118 new_volume Chromosome0014
rosalind-sd: label.c:206 Compare Vol names: VolName= hdr=Chromosome0014
rosalind-sd: label.c:222 Copy vol_name=Chromosome0014
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : Chromosome0014
PrevVolName :
VolFile : 0
LabelType : VOL_LABEL
LabelSize : 185
PoolName : GenePool
MediaType : SDX700-C
PoolType : Backup
HostName : rosalind.partners.org
Date label written: 01-Nov-2005 14:44
<to here>
The information seems to be correct and as expected.
I then log into bacula via bconsole and attempt to relabel an
existing volume (which previously had been purged).
I get the following from my bconsole session:
<From here>
Connecting to Director rosalind:9101
1000 OK: rosalind-dir Version: 1.38.2 (20 November 2005)
Enter a period to cancel a command.
*relabel
Using default Catalog name=MyCatalog DB=bacula
The defined Storage resources are:
1: FileStorage
2: AIT3-Changer
3: GeneSplicer
Select Storage resource (1-3): 3
Connecting to Storage daemon GeneSplicer at rosalind.partners.org:
9103 ...
Defined Pools:
1: BettingPool
2: GenePool
3: Default
4: FilePool
Select the Pool (1-4): 2
+---------+----------------+-----------+-----------------+----------
+--------------+---------+------+-----------+-----------
+---------------------+
| MediaId | VolumeName | VolStatus | VolBytes | VolFiles |
VolRetention | Recycle | Slot | InChanger | MediaType |
LastWritten |
+---------+----------------+-----------+-----------------+----------
+--------------+---------+------+-----------+-----------
+---------------------+
| 59 | Chromosome0006 | Full | 274,268,846,585 | 276
| 31,536,000 | 1 | 1 | 0 | SDX700-C | 2005-05-10
04:25:55 |
| 60 | Chromosome0007 | Full | 171,065,553,008 | 171
| 31,536,000 | 1 | 2 | 1 | SDX700-C | 2005-05-11
17:47:52 |
| 61 | Chromosome0008 | Full | 146,519,620,681 | 166
| 31,536,000 | 1 | 3 | 0 | SDX700-C | 2005-05-31
13:04:09 |
| 62 | Chromosome0009 | Full | 348,134,686,949 | 348
| 31,536,000 | 1 | 4 | 1 | SDX700-C | 2005-06-01
16:06:55 |
| 63 | Chromosome0010 | Full | 174,742,270,016 | 196
| 31,536,000 | 1 | 5 | 1 | SDX700-C | 2005-07-03
06:40:50 |
| 64 | Chromosome0011 | Error | 84,640,368,066 | 86
| 31,536,000 | 1 | 6 | 1 | SDX700-C | 2005-07-15
01:11:48 |
| 65 | Chromosome0012 | Full | 124,586,420,722 | 150
| 31,536,000 | 1 | 7 | 1 | SDX700-C | 2005-08-21
14:24:49 |
| 66 | Chromosome0013 | Full | 197,357,372,843 | 225
| 31,536,000 | 1 | 8 | 1 | SDX700-C | 2005-11-30
18:50:34 |
| 101 | Chromosome0014 | Full | 14,345,016,850 | 14
| 31,536,000 | 1 | 1 | 1 | SDX700-C | 2005-11-30
19:11:35 |
| 102 | Chromosome0016 | Full | 258,084,262,555 | 268
| 31,536,000 | 1 | 3 | 1 | SDX700-C | 2005-12-12
17:37:57 |
| 103 | Chromosome0015 | Purged | 1 | 0
| 31,536,000 | 1 | 2 | 0 | SDX700-C | 0000-00-00
00:00:00 |
| 105 | Chromosome0019 | Purged | 0 | 0
| 31,536,000 | 1 | 6 | 0 | SDX700-C | 0000-00-00
00:00:00 |
| 106 | Chromosome0020 | Recycle | 1 | 0
| 31,536,000 | 1 | 7 | 1 | SDX700-C | 0000-00-00
00:00:00 |
| 107 | Chromosome0021 | Purged | 0 | 0
| 31,536,000 | 1 | 8 | 1 | SDX700-C | 0000-00-00
00:00:00 |
| 108 | Chromosome0017 | Purged | 0 | 0
| 31,536,000 | 1 | 4 | 1 | SDX700-C | 0000-00-00
00:00:00 |
| 109 | Chromosome0018 | Purged | 0 | 0
| 31,536,000 | 1 | 5 | 1 | SDX700-C | 0000-00-00
00:00:00 |
+---------+----------------+-----------+-----------------+----------
+--------------+---------+------+-----------+-----------
+---------------------+
Enter MediaId or Volume name: 103
Enter new Volume name: Chromosome0021
Enter slot (0 or Enter for none): 2
Defined Pools:
1: BettingPool
2: GenePool
3: Default
4: FilePool
Select the Pool (1-4): 2
Connecting to Storage daemon GeneSplicer at rosalind.partners.org:
9103 ...
Sending relabel command from "Chromosome0015" to "Chromosome0021" ...
3301 Issuing autochanger "loaded drive 0" command.
3302 Autochanger "loaded drive 0", result: nothing loaded.
3304 Issuing autochanger "load slot 2, drive 0" command.
3992 Bad autochanger "load slot 2, drive 0": ERR=Child exited with
code 1.
Label command failed for Volume Chromosome0021.
Do not forget to mount the drive!!!
*
<To here>
and the following from my storage daemon ouput:
<From here>
rosalind-sd: label.c:227 Leave read_volume_label() VOL_OK
rosalind-sd: dev.c:655 rewind_dev fd=6 "GeneSplicer" (/dev/nst0)
rosalind-sd: bnet.c:1127 who=client host=170.223.184.136 port=36643
rosalind-sd: dircmd.c:157 Conn: Hello Director rosalind-dir calling
rosalind-sd: dircmd.c:166 Start Dir Job
rosalind-sd: cram-md5.c:52 send: auth cram-md5
<[EMAIL PROTECTED]> ssl=0
rosalind-sd: cram-md5.c:68 Authenticate OK +h+Mj64Hz8gQ0XsHllEWGC
rosalind-sd: cram-md5.c:97 cram-get: auth cram-md5
<[EMAIL PROTECTED]> ssl=0
rosalind-sd: cram-md5.c:114 sending resp to challenge: S6/pq8ACo6
+Ot79rfx/7gD
rosalind-sd: dircmd.c:187 Message channel init completed.
rosalind-sd: dircmd.c:194 <dird: autochanger drives GeneSplicer
rosalind-sd: dircmd.c:208 Do command: autochanger
rosalind-sd: dircmd.c:501 Found device GeneSplicer
rosalind-sd: dircmd.c:539 Found changer device GeneSplicer
rosalind-sd: autochanger.c:431 drives=1
rosalind-sd: bnet.c:1127 who=client host=170.223.184.136 port=36643
rosalind-sd: dircmd.c:157 Conn: Hello Director rosalind-dir calling
rosalind-sd: dircmd.c:166 Start Dir Job
rosalind-sd: cram-md5.c:52 send: auth cram-md5
<[EMAIL PROTECTED]> ssl=0
rosalind-sd: cram-md5.c:68 Authenticate OK u5l77T/S06seY/+qkT1aCC
rosalind-sd: cram-md5.c:97 cram-get: auth cram-md5
<[EMAIL PROTECTED]> ssl=0
rosalind-sd: cram-md5.c:114 sending resp to challenge: 7lZvo9/lf+1DV+/
PFmc9FD
rosalind-sd: dircmd.c:187 Message channel init completed.
rosalind-sd: dircmd.c:194 <dird: relabel GeneSplicer
OldName=Chromosome0015 NewName=Chromosome0021 PoolName=GenePool
MediaType=SDX700-C Slot=2 drive=0
rosalind-sd: dircmd.c:208 Do command: relabel
rosalind-sd: dircmd.c:501 Found device GeneSplicer
rosalind-sd: dircmd.c:539 Found changer device GeneSplicer
rosalind-sd: dircmd.c:351 Can relabel. device not used
rosalind-sd: device.c:433 steal lock. old=BST_NOT_BLOCKED from
dircmd.c:387
rosalind-sd: device.c:438 steal lock. new=BST_WRITING_LABEL
rosalind-sd: dircmd.c:388 Stole device "GeneSplicer" (/dev/nst0)
lock, writing label.
rosalind-sd: autochanger.c:121 Want changer slot=2
rosalind-sd: autochanger.c:246 Locking changer AIT3-Changer
rosalind-sd: bpipe.c:291 Run program returning 0
rosalind-sd: autochanger.c:217 run_prog: /etc/bacula/mtx-changer /dev/
sg1 loaded 2 /dev/nst0 0 stat=0 result=Doing mtx -f /dev/sg1 0 -- to
find what is loaded
rosalind-sd: autochanger.c:255 Unlocking changer AIT3-Changer
rosalind-sd: autochanger.c:246 Locking changer AIT3-Changer
rosalind-sd: autochanger.c:146 Doing changer load slot 2
Drive 0 Full (Storage Element 1 loaded)
rosalind-sd: bpipe.c:291 Run program returning 268435457
rosalind-sd: autochanger.c:165 load slot 2 status=268435457
rosalind-sd: autochanger.c:255 Unlocking changer AIT3-Changer
rosalind-sd: autochanger.c:171 After changer, status=268435457
rosalind-sd: device.c:450 return lock. old=BST_WRITING_LABEL from
dircmd.c:445
rosalind-sd: device.c:455 return lock. new=BST_NOT_BLOCKED
./bconsole
<to here>
As you can see, I am getting the dreaded "3992 Bad autochanger "load
slot 2, drive 0": ERR=Child exited with code 1." but I can't see
anything in the storage daemon output to indicate a problem. My
permissions are OK and I believe that my config files are ok too. Can
anyone give a clue where to continue looking for this issue?
John Hayden
Systems Administrator
Brigham & Women's Hospital - Genetics Division
77 Avenue Louis Pasteur
Boston, MA 02115
617-525-4748
-------------------------------------------------------
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
