Cannot find any appendable volumes – Bacula

A problem arose today which I have never seen before. I do not know what caused it and I do not know precisely how I fixed it.

I am using Baclua 7.0.5 on FreeBSD 9.3

I found this email today:

From: root@localhost.example.org (Bacula)
Subject: Bacula: Intervention needed for slocum_jail_snapshots.2015-01-25_05.55.01_01
Sender: bacula@bacula.example.org
To: root@localhost.example.org
Date: Sun, 25 Jan 2015 08:19:49 +0000 (UTC)
Message-Id: <20150125081949.ABF3A2AF8@bacula.example.org>
X-Gm-Original-To: dan@example.org

25-Jan 08:19 crey-sd JobId 197628: Job slocum_jail_snapshots.2015-01-25_05.55.01_01 is waiting. Cannot find any appendable volumes.
Please use the "label" command to create a new Volume for:
    Storage:      "CreyFile" (/usr/local/bacula/volumes)
    Pool:         DiffFile
    Media type:   File

This is Bacula asking for more ‘tape’. I say tape, because that is an easy analogy to follow. In effect, the tape library has no tapes to which Bacula can place this backup. They are all full (with respect to the given type of tape required). In this case, it’s the Pool called DiffFile. That’s a Pool for Differential backups.

In this particular case, the backup is not using tapes, it’s using disk. A Volume, in Bacula terms, is a place for backups within a Storage Daemon.

The Pool definition in question is:

Pool {
  Name             = DiffFile
  Pool Type        = Backup
  Recycle          = yes
  AutoPrune        = yes
  Volume Retention = 6 weeks
  Storage          = CreyFile
  Next Pool        = Differentials

  Maximum Volume Bytes = 5G

  Maximum Volumes  = 80

  LabelFormat = "DiffAuto-"
}

As shown, there is a maximum of 80 Volumes, each 5G in size, for a total of 400G.

I need to increase this Pool size. I will give it another 50G of storage, or 10 more Volumes. I’ll just change line 12 from 80 to 90.

The next step is telling Bacula about this change. I issue the reload command within bconsole:

*reload
*

NOTE: this next step is not required. The reload command has already done this.

I also need to update the Pool definition in the database. That is accomplished with the update command:

*update
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
Update choice:
     1: Volume parameters
     2: Pool from resource
     3: Slots from autochanger
     4: Long term statistics
Choose catalog item to update (1-4): 2
The defined Pool resources are:
     1: Default
     2: FullFile
     3: DiffFile
     4: IncrFile
     5: IncrFileNoNextPool
     6: FullFileNoNextPool
     7: Fulls
     8: Differentials
     9: Incrementals
    10: Scratch
    11: TwoHourlyBackups
    12: DailyBackups
    13: WeeklyBackups
    14: MonthlyBackups
    15: KeepThreeMonths
Select Pool resource (1-15): 3
+--------+----------+---------+---------+---------+------------+-----------------+--------------+----------------+------------+-------------+---------------+-----------+---------+----------+-------------+---------+---------------+---------------+-----------+------------+--------------------+-------------------+---------------+---------------+
| poolid | name     | numvols | maxvols | useonce | usecatalog | acceptanyvolume | volretention | voluseduration | maxvoljobs | maxvolfiles | maxvolbytes   | autoprune | recycle | pooltype | labelformat | enabled | scratchpoolid | recyclepoolid | labeltype | nextpoolid | migrationhighbytes | migrationlowbytes | migrationtime | actiononpurge |
+--------+----------+---------+---------+---------+------------+-----------------+--------------+----------------+------------+-------------+---------------+-----------+---------+----------+-------------+---------+---------------+---------------+-----------+------------+--------------------+-------------------+---------------+---------------+
|     23 | DiffFile |      80 |      90 |       0 |          1 |               0 |    3,628,800 |              0 |          0 |           0 | 5,368,709,120 |         1 |       1 | Backup   | DiffAuto-   |       1 |             0 |             0 |         0 |            |                    |                   |               |             0 |
+--------+----------+---------+---------+---------+------------+-----------------+--------------+----------------+------------+-------------+---------------+-----------+---------+----------+-------------+---------+---------------+---------------+-----------+------------+--------------------+-------------------+---------------+---------------+
Pool DB record updated from resource.
*

Did that work?

No.

*m
25-Jan 16:18 bacula-dir JobId 197628: Created new Volume="DiffAuto-4496", Pool="DiffFile", MediaType="File" in catalog.
25-Jan 16:18 crey-sd JobId 197628: Warning: mount.c:212 Open of file device "CreyFile" (/usr/local/bacula/volumes) Volume "DiffAuto-4496" failed: ERR=file_dev.c:172 Could not open(/usr/local/bacula/volumes/DiffAuto-4496,OPEN_READ_WRITE,0640): ERR=No such file or directory

25-Jan 16:18 crey-sd JobId 197628: Warning: mount.c:212 Open of file device "CreyFile" (/usr/local/bacula/volumes) Volume "DiffAuto-4496" failed: ERR=file_dev.c:172 Could not open(/usr/local/bacula/volumes/DiffAuto-4496,OPEN_READ_WRITE,0640): ERR=No such file or directory

25-Jan 16:18 crey-sd JobId 197628: Warning: mount.c:212 Open of file device "CreyFile" (/usr/local/bacula/volumes) Volume "DiffAuto-4496" failed: ERR=file_dev.c:172 Could not open(/usr/local/bacula/volumes/DiffAuto-4496,OPEN_READ_WRITE,0640): ERR=No such file or directory

25-Jan 16:18 crey-sd JobId 197628: Warning: mount.c:212 Open of file device "CreyFile" (/usr/local/bacula/volumes) Volume "DiffAuto-4496" failed: ERR=file_dev.c:172 Could not open(/usr/local/bacula/volumes/DiffAuto-4496,OPEN_READ_WRITE,0640): ERR=No such file or directory

25-Jan 16:18 crey-sd JobId 197628: Warning: mount.c:212 Open of file device "CreyFile" (/usr/local/bacula/volumes) Volume "DiffAuto-4496" failed: ERR=file_dev.c:172 Could not open(/usr/local/bacula/volumes/DiffAuto-4496,OPEN_READ_WRITE,0640): ERR=No such file or directory

*

It does not seem to be a permissions issue:

[dan@crey:/usr/local/bacula/volumes] $ ls -ld .
drwxr-xr-x  4 bacula  bacula  2419 Jan 25 08:18 .
[dan@crey:/usr/local/bacula/volumes] $ ps auwx | grep bacula-sd
bacula 59677  0.0  0.1 176476 46916 ??  IsJ  Wed08PM 350:35.71 /usr/local/sbin/bacula-sd -u bacula -g bacula -v -c /usr/local/etc/bacula/bacula-sd.conf
dan    26645  0.0  0.0  12236  1840  0  R+J   4:25PM   0:00.00 grep bacula-sd
[dan@crey:/usr/local/bacula/volumes] $ 

Here is the Storage definition (from bacula-dir.conf):

# Definiton of file storage device
Storage {
  Name       = CreyFile
  Address    = crey.int.example.org
  SDPort     = 9103
  Password   = "Mo7G6/3e8uROkUBPcDDdJion13ZLcYo/4GeecIT0eg85"
  Device     = CreyFile
  Media Type = File

  Maximum Concurrent Jobs = 40
}

Here is the device (from bacula-sd.conf):

Device {
  Name           = CreyFile
  Media Type     = File
  Archive Device = /usr/local/bacula/volumes
  LabelMedia     = yes
  Random Access  = yes
  AutomaticMount = yes
  RemovableMedia = no
  AlwaysOpen     = no
}

That looks good.

The Volume has been created, based on the output of list volumes pool=DiffFile:

|   4,496 | DiffAuto-4496 | Append    |       1 |             0 |        0 |    3,628,800 |       1 |    0 |         0 | File      |                     

Let’s try a delete and label that Volume manually:

Enter *MediaId or Volume name: DiffAuto-4496

This command will delete volume DiffAuto-4496
and all Jobs saved on that volume from the Catalog
Are you sure you want to delete Volume "DiffAuto-4496"? (yes/no): yes
You have messages.
*m
25-Jan 17:13 crey-sd JobId 197628: Warning: mount.c:212 Open of file device "CreyFile" (/usr/local/bacula/volumes) Volume "DiffAuto-4496" failed: ERR=file_dev.c:172 Could not open(/usr/local/bacula/volumes/DiffAuto-4496,OPEN_READ_WRITE,0640): ERR=No such file or directory

*label
The defined Storage resources are:
     1: File
     2: DLT
     3: CreyFile
     4: CompaqStorageWorksTapeLibrary
Select Storage resource (1-4): 3
Enter new Volume name: DiffAuto-4496
Defined Pools:
     1: FullFile
     2: IncrFile
     3: IncrFileNoNextPool
     4: FullFileNoNextPool
     5: Scratch
     6: TwoHourlyBackups
     7: DailyBackups
     8: WeeklyBackups
     9: MonthlyBackups
    10: Fulls
    11: Differentials
    12: Incrementals
    13: KeepThreeMonths
    14: DiffFile
    15: Default
Select the Pool (1-15): 14
Connecting to Storage daemon CreyFile at crey.int.unixathome.org:9103 ...
Sending label command for Volume "DiffAuto-4496" Slot 0 ...
3000 OK label. VolBytes=195 DVD=0 Volume="DiffAuto-4496" Device="CreyFile" (/usr/local/bacula/volumes)
Catalog record for Volume "DiffAuto-4496", Slot 0  successfully created.
Requesting to mount CreyFile ...
3001 OK mount requested. Device="CreyFile" (/usr/local/bacula/volumes)
*m
25-Jan 17:13 crey-sd JobId 197628: Wrote label to prelabeled Volume "DiffAuto-4496" on file device "CreyFile" (/usr/local/bacula/volumes)
25-Jan 17:13 crey-sd JobId 197628: New volume "DiffAuto-4496" mounted on device "CreyFile" (/usr/local/bacula/volumes) at 25-Jan-2015 17:13.
*

That seems to have worked. The Volume exists and is getting larger:

[dan@crey:/usr/local/bacula/volumes] $ ls -l DiffAuto-4496
-rw-r-----  1 bacula  bacula  1406813379 Jan 25 17:13 DiffAuto-4496
[dan@crey:/usr/local/bacula/volumes] $ ls -l DiffAuto-4496
-rw-r-----  1 bacula  bacula  1625380035 Jan 25 17:13 DiffAuto-4496
[dan@crey:/usr/local/bacula/volumes] $ 

I have no idea what went wrong.

But look here:

*m
25-Jan 17:21 crey-sd JobId 197628: End of medium on Volume "DiffAuto-4496" Bytes=5,368,688,835 Blocks=83,220 at 25-Jan-2015 17:21.
25-Jan 17:21 bacula-dir JobId 197628: Created new Volume="DiffAuto-4498", Pool="DiffFile", MediaType="File" in catalog.
25-Jan 17:21 crey-sd JobId 197628: Labeled new Volume "DiffAuto-4498" on file device "CreyFile" (/usr/local/bacula/volumes).
25-Jan 17:21 crey-sd JobId 197628: Wrote label to prelabeled Volume "DiffAuto-4498" on file device "CreyFile" (/usr/local/bacula/volumes)
25-Jan 17:21 crey-sd JobId 197628: New volume "DiffAuto-4498" mounted on device "CreyFile" (/usr/local/bacula/volumes) at 25-Jan-2015 17:21.
*

The next volume was 4498, not 4497. Symptom? Or cause?

The rest of the backups finished without issue.