ttt: (FreeBSD, Bacula) The number of files mismatch! Volume=3 Catalog=4

ネットワークベースのバックアップソフト「Bacula」で、毎日、複数台のコンピュータのデータのバックアップを採っています。バックアップ先は、ほとんどはハードディスクで、１つだけ、ためしに、古いテープライブラリ（オートチェンジャーつきのテープドライブ。ジュークボックス。メディアはDLT7000）も使ってます。

先週か、先々週くらいに気がついたのですが、ボリュームの一覧を見たら、テープライブラリ内テープすべてで、Volume Statusが、Errorになってました。そのときは、う～んまいったな、古いテープだからエラーになったのかな？と思うだけで、volumeをすべてpurgeして、relabelしてしまいました。つまり、テープ内のデータをすべて破棄して、空の状態から、またテープを使うようにしました。

テープドライブのクリーニングをやってなかったので、そのせいかな？とか思ってたのですが、クリーニングを実行し、数日後のぞいてみると、やっぱりまた、Volume StatusがErrorに。

毎日メールで送られてくるログメッセージを見直してみると、こんな気になることが書かれていました。

hogetape-dir JobId 6468: Start Backup JobId 6468, Job=Client2.2007-11-07_23.05.31
hogetape-dir JobId 6468: Using Device "Drive-1"
hogetape-sd JobId 6468: 3301 Issuing autochanger "loaded? drive 0" command.
hogetape-sd JobId 6468: 3302 Autochanger "loaded? drive 0", result is Slot 4.
hogetape-sd JobId 6468: Volume "TAPE022" previously written, moving to end of data.
hogetape-sd JobId 6468: Error: Bacula cannot write on tape Volume "TAPE022" because:
The number of files mismatch! Volume=3 Catalog=4
hogetape-sd JobId 6468: Marking Volume "TAPE022" in Error in Catalog.
hogetape-sd JobId 6468: 3307 Issuing autochanger "unload slot 4, drive 0" command.
hogetape-sd JobId 6468: 3304 Issuing autochanger "load slot 3, drive 0" command.
hogetape-sd JobId 6468: 3305 Autochanger "load slot 3, drive 0", status is OK.
hogetape-sd JobId 6468: 3301 Issuing autochanger "loaded? drive 0" command.
hogetape-sd JobId 6468: 3302 Autochanger "loaded? drive 0", result is Slot 3.
hogetape-sd JobId 6468: Wrote label to prelabeled Volume "TAPE023" on device "Drive-1" (/dev/nsa0)

気になるのはココです。

The number of files mismatch! Volume=3 Catalog=4

カタログ（MySQLのデータベース）には4個のデータがあることになっているのに、テープの中には3個しかない。

それはおかしいから、このテープを使うのはやめにして、別のテープを使うことにするよ。

ってことのようですね。

テープってのは、前回のバックアップ記録時、テープの途中までしか使ってなければ（たいていそう）、今回は、前回のつづき、途中から続けて、データを追記していくらしいです。

さて、続きの場所を読んでみたら、最後に記録したデータの番号と、データベース中に覚えていた番号とが不一致してる、ってわけで、それってそのテープが変なんじゃない？　ってことで使うのをやめて、ステータスをErrorにされてしまうんでしょうね。

以前は、ちゃんとテープに追加書き込みができていたし、リストアもできてたんですが、いつからこうなってしまったのか・・・？

思い当たるのは

bacula-2.2.5へアップデートした

FreeBSD 7.0-BETA1へアップデートした

くらいです。

昔の環境へ戻す、という方法もあるでしょうが、それってかなり後ろ向き、って思うので、今回、それはやめておこう、ということにしました。

☆

btapeというコマンドで、テープドライブがBaculaでちゃんと使えるか、テストできます。

# btape -c /usr/local/etc/bacula-sd.conf /dev/nsa0
Tape block granularity is 1024 bytes.
btape: butil.c:285 Using device: "/dev/nsa0" for writing.
08-11 10:56 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
08-11 10:56 btape JobId 0: 3302 Autochanger "loaded? drive 0", result is Slot 1.
08-11 10:56 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
08-11 10:56 btape JobId 0: 3302 Autochanger "loaded? drive 0", result is Slot 1.
btape: btape.c:368 open device "Drive-1" (/dev/nsa0): OK
*test　（と入力）

（～省略～）

=== Append files test ===　テープへの追加書き込みをテストするらしい

This test is essential to Bacula.

I'm going to write one record in file 0,
two records in file 1,
and three records in file 2

btape: btape.c:471 Rewound "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
08-11 10:29 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
08-11 10:29 btape JobId 0: 3302 Autochanger "loaded? drive 0", result is Slot 3.
btape: btape.c:368 open device "Drive-1" (/dev/nsa0): OK
btape: btape.c:471 Rewound "Drive-1" (/dev/nsa0)
btape: btape.c:1093 Now moving to end of medium.
btape: btape.c:522 Moved to end of medium.
We should be in file 3. I am at file 2. This is NOT correct!!!!
Append test failed. Attempting again.
Setting "Hardware End of Medium = no
and "Fast Forward Space File = no
and retrying append test.

（失敗したので、設定を変えて、もう一度テストするらしい）

=== Append files test ===

This test is essential to Bacula.

I'm going to write one record in file 0,
two records in file 1,
and three records in file 2

btape: btape.c:471 Rewound "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
08-11 10:30 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
08-11 10:30 btape JobId 0: 3302 Autochanger "loaded? drive 0", result is Slot 3.
btape: btape.c:368 open device "Drive-1" (/dev/nsa0): OK
btape: btape.c:471 Rewound "Drive-1" (/dev/nsa0)
btape: btape.c:1093 Now moving to end of medium.
btape: btape.c:522 Moved to end of medium.
We should be in file 3. I am at file 2. This is NOT correct!!!!

That appears *NOT* to have corrected the problem.

Append test failed.　（失敗したぞ）

!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Unable to correct the problem. You MUST fix this
problem before Bacula can use your tape drive correctly
（この問題を解決しない限り、Baculaではこのテープドライブは使えないねぇ）

Perhaps running Bacula in fixed block mode will work.
Do so by setting:

Minimum Block Size = nnn
Maximum Block Size = nnn

in your Storage daemon's Device definition.
nnn must match your tape driver's block size, which
can be determined by reading your tape manufacturers
information, and the information on your kernel dirver.
Fixed block sizes, however, are not normally an ideal solution.

Some systems, e.g. OpenBSD, require you to set
Use MTIOCGET= no
in your device resource. Use with caution.

なんかいろいろメッセージが出てきましたが、Baculaのドキュメントを探していたら、これが見つかりました。

Tape Modes on FreeBSD
http://www.bacula.org/dev-manual/Testing_Your_Tape_Drive.html#SECTION004037000000000000000

これによれば、こんなコマンドを実行しておけ、とのこと。

# mt -f /dev/nsa0 seteotmodel 2
/dev/nsa0: old model was 1 filemark at EOT
/dev/nsa0: new model is 2 filemarks at EOT
# mt -f /dev/nsa0 blocksize 0
# mt -f /dev/nsa0 comp enable

え！？こんなの、ぜんぜん知りませんでした。
で、やってみて、もう一度btapeでtestを実行したのですが、やっぱりダメ。

もうちょっとドキュメントをちゃんと読んでみました。

bacula-sd.confにて、Deviceの設定を書け、と言ってます。
ただ、どう書けばいいのかは、使っているハードウェアによって異なるみたいです。

とりあえず、推奨されているものをためしたら、うまくいきました。

=== Append files test ===

This test is essential to Bacula.

I'm going to write one record in file 0,
two records in file 1,
and three records in file 2

btape: btape.c:471 Rewound "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
08-11 11:04 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
08-11 11:04 btape JobId 0: 3302 Autochanger "loaded? drive 0", result is Slot 1.
btape: btape.c:368 open device "Drive-1" (/dev/nsa0): OK
btape: btape.c:471 Rewound "Drive-1" (/dev/nsa0)
btape: btape.c:1093 Now moving to end of medium.
btape: btape.c:522 Moved to end of medium.
We should be in file 3. I am at file 3. This is correct!

Now the important part, I am going to attempt to append to the tape.

btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:471 Rewound "Drive-1" (/dev/nsa0)
Done appending, there should be no I/O errors

Doing Bacula scan of blocks:
1 block of 64448 bytes in file 1
End of File mark.
2 blocks of 64448 bytes in file 2
End of File mark.
3 blocks of 64448 bytes in file 3
End of File mark.
1 block of 64448 bytes in file 4
End of File mark.
Total files=4, blocks=7, bytes = 451,136
End scanning the tape.
We should be in file 4. I am at file 4. This is correct!

The above Bacula scan should have output identical to what follows.
Please double check it ...
=== Sample correct output ===
1 block of 64448 bytes in file 1
End of File mark.
2 blocks of 64448 bytes in file 2
End of File mark.
3 blocks of 64448 bytes in file 3
End of File mark.
1 block of 64448 bytes in file 4
End of File mark.
Total files=4, blocks=7, bytes = 451,136
=== End sample correct output ===

If the above scan output is not identical to the
sample output, you MUST correct the problem
or Bacula will not be able to write multiple Jobs to
the tape.

Skipping read backwards test because BSR turned off.

=== Forward space files test ===

This test is essential to Bacula.

I'm going to write five files then test forward spacing

btape: btape.c:471 Rewound "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:1573 Wrote one record of 64412 bytes.
btape: btape.c:1575 Wrote block to device.
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:501 Wrote 1 EOF to "Drive-1" (/dev/nsa0)
btape: btape.c:471 Rewound "Drive-1" (/dev/nsa0)
btape: btape.c:1307 Now forward spacing 1 file.
We should be in file 1. I am at file 1. This is correct!
btape: btape.c:1319 Now forward spacing 2 files.
We should be in file 3. I am at file 3. This is correct!
btape: btape.c:471 Rewound "Drive-1" (/dev/nsa0)
btape: btape.c:1332 Now forward spacing 4 files.
We should be in file 4. I am at file 4. This is correct!

btape: btape.c:1350 Now forward spacing 1 more file.
We should be in file 5. I am at file 5. This is correct!

=== End Forward space files test ===

Ah, I see you have an autochanger configured.
To test the autochanger you must have a blank tape
that I can write on in Slot 1.

Do you wish to continue with the Autochanger test? (y/n): y

=== Autochanger test ===

3301 Issuing autochanger "loaded" command.
Slot 1 loaded. I am going to unload it.
3302 Issuing autochanger "unload 1 0" command.
unload status=OK 0
3303 Issuing autochanger "load 1 0" command.
3303 Autochanger "load 1 0" status is OK.
08-11 11:41 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
08-11 11:41 btape JobId 0: 3302 Autochanger "loaded? drive 0", result is Slot 1.
btape: btape.c:368 open device "Drive-1" (/dev/nsa0): OK
btape: btape.c:1237 Rewound "Drive-1" (/dev/nsa0)
btape: btape.c:1244 Wrote EOF to "Drive-1" (/dev/nsa0)

The test autochanger worked!!

追加したのは、

BSF at EOM = yes
Backward Space Record = no
Backward Space File = no
Fast Forward Space File = no
TWO EOF = yes

でした。今では、bacula-sd.confは、こんな感じになりました。

Device {
Name = Drive-1 #
Drive Index = 0
Media Type = DLT7000
Archive Device = /dev/nsa0
AutomaticMount = yes; # when device opened, read it
AlwaysOpen = yes;
RemovableMedia = yes;
RandomAccess = no;
AutoChanger = yes
Hardware End of Medium = no
BSF at EOM = yes
Backward Space Record = no
Backward Space File = no
Fast Forward Space File = no
TWO EOF = yes
# Enable the Alert command only if you have the mtx package loaded
Alert Command = "sh -c '/usr/local/sbin/tapeinfo -f %c |grep TapeAlert|cat'"
}