Veritas-bu

[Veritas-bu] Worrying bptm log entry and 84 error later on

2005-01-10 19:11:33
Subject: [Veritas-bu] Worrying bptm log entry and 84 error later on
From: thoke AT northpeak DOT org (Tim Hoke)
Date: Mon, 10 Jan 2005 18:11:33 -0600
--Apple-Mail-1-393558136
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain;
        charset=WINDOWS-1252;
        format=flowed

Marshall,

First off, the "unable to lock media" is totally normal.  It's likely=20
that either a bptm -U or some other process came in and was trying to=20
select that piece of media.  It's good that it shows up as locked. =20
That way, no other process can grab it and use it.

Second, you'll need to see the bptm log at the time of the error. =20
Additionally, you'll need to look at the syslog during that same time. =20=

So, what do bptm and syslog say?

You say you're on 4.5 GA.  Is that really the case?  You should be=20
patched up from there as GA is a REALLY old release by now.

-Tim

On Jan 10, 2005, at 4:49 PM, <marshall.a.skare AT accenture DOT com> wrote:

> Hi everyone,
>
> =A0
>
> I=92m trying to track down the cause of some 84 and 14 failures we=92ve=20=

> been having lately.=A0 I know the problem is not tape, drive, job,=20
> time-of-day or robot specific.=A0 However the problem seems to be=20
> happening on the weekends when we run our full backups.=A0 We=92re on =
NBU=20
> 4.5GA running on Solaris 8 master and media servers with an STK L700=20=

> library that has Seagate Viper 200s in it.
>
> =A0
>
> One of the entries I found in a bptm log bothered me a little bit.=A0 =
Is=20
> this normal, or should I perform an inventory on the robot?=A0 The =
first=20
> line says the media is not in the correct storage unit or volume=20
> pool.=A0 However, it looks like the tape ends up being used anyway, =
and=20
> it also appears that the tape was able to store data. =A0The job=20
> associated with these log entries bombed out roughly 4 hours later=20
> with an 84 error.
>
> =A0
>
> Also, during the whole backup attempt, I=92d see the db_lock_media =
error=20
> messages about every 30 seconds.=A0 I=92ve read elsewhere that this =
isn=92t=20
> really a problem.
>
> =A0
>
> 20:19:23.649 [13116] <2> select_media: skipping media id 000309, it is=20=

> not in correct storage unit or volume pool
>
> 22:09:35.428 [13711] <2> check_available_drives: checking drives,=20
> about to request media id 000309
>
> 22:09:35.589 [13711] <2> select_media: selected media id 000309 for=20
> backup[0], crmmnt52(rl =3D 4) <----------
>
> 22:09:35.592 [13711] <2> mount_open_media: Waiting for mount of media=20=

> id 000309 (copy 1) on server crmmdb17.
>
> 22:09:58.590 [13725] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:10:24.370 [13739] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:10:27.510 [13746] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:10:31.100 [13754] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:10:50.500 [13761] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:10:52.710 [13768] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:11:00.730 [13775] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:11:05.320 [13783] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:11:24.389 [13711] <2> io_open: file=20
> /usr/openv/netbackup/db/media/tpreq/000309 successfully opened
>
> 22:11:24.389 [13711] <2> write_backup: media id 000309 mounted on=20
> drive index 0, drivepath /dev/rmt/8cbn, drivename LTO_crmmdb17_0, copy=20=

> 1
>
> 22:11:24.588 [13711] <2> io_position_for_write: position media id=20
> 000309, copy 1, current number images =3D 23
>
> 22:11:25.220 [13790] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:11:36.810 [13799] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:11:59.039 [13711] <2> io_position_for_write: empty header found on=20=

> 000309, OK, copy 1
>
> 22:11:59.039 [13711] <2> io_close: closing=20
> /usr/openv/netbackup/db/media/tpreq/000309, from bptm.c.17346
>
> 22:11:59.046 [13711] <2> io_open: file=20
> /usr/openv/netbackup/db/media/tpreq/000309 successfully opened
>
> 22:12:07.410 [13807] <2> db_lock_media: unable to lock media at offset=20=

> 63 (000309)
>
> 22:12:22.924 [13711] <4> write_backup: begin writing backup id=20
> crmmnt52_1105157367, copy 1, fragment 1, to media id 000309 on drive=20=

> index 0
>
> =A0
>
> If our problem is really network-related, are there any unusual causes=20=

> I should check first?=A0 The clients we=92re backing up are a mixture =
of=20
> Solaris 7/8 and Windows XP/2000 Server/2003 Server.=A0 I think I=92ve=20=

> ruled out the drives altogether since I took the time to run TapeRx on=20=

> all of the drives in this system, and have written and read up to 4GB=20=

> without an error.=A0 I=92ve had backup jobs fail with error 84 that =
have=20
> transferred less data than that when they failed.
>
> =A0
>
> Thanks for any help!
>
> =A0
>
> Marshall Skare
>
> ATIS - Unix Engineering
>
> (612) 277-4434
>
> =A0
>
> This message is for the designated recipient only and may contain=20
> privileged, proprietary, or otherwise private information. If you have=20=

> received it in error, please notify the sender immediately and delete=20=

> the original. Any other use of the email by you is prohibited.

--Apple-Mail-1-393558136
Content-Transfer-Encoding: quoted-printable
Content-Type: text/enriched;
        charset=WINDOWS-1252

Marshall,


First off, the "unable to lock media" is totally normal.  It's likely
that either a bptm -U or some other process came in and was trying to
select that piece of media.  It's good that it shows up as locked.=20
That way, no other process can grab it and use it.


Second, you'll need to see the bptm log at the time of the error.=20
Additionally, you'll need to look at the syslog during that same time.=20=

So, what do bptm and syslog say?


You say you're on 4.5 GA.  Is that really the case?  You should be
patched up from there as GA is a REALLY old release by now.


-Tim


On Jan 10, 2005, at 4:49 PM, <<marshall.a.skare AT accenture DOT com> wrote:


<excerpt><fontfamily><param>Arial</param><x-tad-bigger>Hi =
everyone,</x-tad-bigger></fontfamily>


=
<fontfamily><param>Arial</param><x-tad-bigger>=A0</x-tad-bigger></fontfami=
ly>


<fontfamily><param>Arial</param><x-tad-bigger>I=92m trying to track down
the cause of some 84 and 14 failures we=92ve been having lately.=A0 I =
know
the problem is not tape, drive, job, time-of-day or robot specific.=A0
However the problem seems to be happening on the weekends when we run
our full backups.=A0 We=92re on NBU 4.5GA running on Solaris 8 master =
and
media servers with an STK L700 library that has Seagate Viper 200s in
it.</x-tad-bigger></fontfamily>


=
<fontfamily><param>Arial</param><x-tad-bigger>=A0</x-tad-bigger></fontfami=
ly>


<fontfamily><param>Arial</param><x-tad-bigger>One of the entries I
found in a
</x-tad-bigger></fontfamily><fixed><fontfamily><param>Courier =
New</param><x-tad-bigger>bptm</x-tad-bigger></fontfamily></fixed><fontfami=
ly><param>Arial</param><x-tad-bigger>
log bothered me a little bit.=A0 Is this normal, or should I perform an
inventory on the robot?=A0 The first line says the media is not in the
correct storage unit or volume pool.=A0 However, it looks like the tape
ends up being used anyway, and it also appears that the tape was able
to store data. =A0The job associated with these log entries bombed out
roughly 4 hours later with an 84 error.</x-tad-bigger></fontfamily>


=
<fontfamily><param>Arial</param><x-tad-bigger>=A0</x-tad-bigger></fontfami=
ly>


<fontfamily><param>Arial</param><x-tad-bigger>Also, during the whole
backup attempt, I=92d see the
</x-tad-bigger></fontfamily><fixed><fontfamily><param>Courier =
New</param><x-tad-bigger>db_lock_media</x-tad-bigger></fontfamily></fixed>=
<fontfamily><param>Arial</param><x-tad-bigger>
error messages about every 30 seconds.=A0 I=92ve read elsewhere that =
this
isn=92t really a problem.</x-tad-bigger></fontfamily>


=
<fontfamily><param>Arial</param><x-tad-bigger>=A0</x-tad-bigger></fontfami=
ly>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>20:19:23.649
[13116] <<2> select_media: skipping media id 000309, it is not in
correct storage unit or volume pool</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:09:35.428
[13711] <<2> check_available_drives: checking drives, about to request
media id 000309</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:09:35.589
[13711] <<2> select_media: selected media id 000309 for backup[0],
crmmnt52(rl =3D 4) <<----------</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:09:35.592
[13711] <<2> mount_open_media: Waiting for mount of media id 000309
(copy 1) on server crmmdb17.</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:09:58.590
[13725] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:10:24.370
[13739] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:10:27.510
[13746] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:10:31.100
[13754] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:10:50.500
[13761] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:10:52.710
[13768] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:11:00.730
[13775] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:11:05.320
[13783] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:11:24.389
[13711] <<2> io_open: file /usr/openv/netbackup/db/media/tpreq/000309
successfully opened</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:11:24.389
[13711] <<2> write_backup: media id 000309 mounted on drive index 0,
drivepath /dev/rmt/8cbn, drivename LTO_crmmdb17_0, copy =
1</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:11:24.588
[13711] <<2> io_position_for_write: position media id 000309, copy 1,
current number images =3D 23</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:11:25.220
[13790] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:11:36.810
[13799] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:11:59.039
[13711] <<2> io_position_for_write: empty header found on 000309, OK,
copy 1</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:11:59.039
[13711] <<2> io_close: closing
/usr/openv/netbackup/db/media/tpreq/000309, from =
bptm.c.17346</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:11:59.046
[13711] <<2> io_open: file /usr/openv/netbackup/db/media/tpreq/000309
successfully opened</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:12:07.410
[13807] <<2> db_lock_media: unable to lock media at offset 63 =
(000309)</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier New</param><x-tad-bigger>22:12:22.924
[13711] <<4> write_backup: begin writing backup id
crmmnt52_1105157367, copy 1, fragment 1, to media id 000309 on drive
index 0</x-tad-bigger></fontfamily></fixed>


<fixed><fontfamily><param>Courier =
New</param><x-tad-bigger>=A0</x-tad-bigger></fontfamily></fixed>


<fontfamily><param>Arial</param><x-tad-bigger>If our problem is really
network-related, are there any unusual causes I should check first?=A0
The clients we=92re backing up are a mixture of Solaris 7/8 and Windows
XP/2000 Server/2003 Server.=A0 I think I=92ve ruled out the drives
altogether since I took the time to run TapeRx on all of the drives in
this system, and have written and read up to 4GB without an error.=A0
I=92ve had backup jobs fail with error 84 that have transferred less
data than that when they failed.</x-tad-bigger></fontfamily>


=
<fontfamily><param>Arial</param><x-tad-bigger>=A0</x-tad-bigger></fontfami=
ly>


<fontfamily><param>Arial</param><x-tad-bigger>Thanks for any =
help!</x-tad-bigger></fontfamily>


=
<fontfamily><param>Arial</param><x-tad-bigger>=A0</x-tad-bigger></fontfami=
ly>


<fontfamily><param>Arial</param><x-tad-bigger>Marshall =
Skare</x-tad-bigger></fontfamily>


<fontfamily><param>Arial</param><x-tad-bigger>ATIS - Unix =
Engineering</x-tad-bigger></fontfamily>


<fontfamily><param>Arial</param><x-tad-bigger>(612) =
277-4434</x-tad-bigger></fontfamily>


<fontfamily><param>Book Antiqua</param><smaller>=A0</smaller></fontfamily>=



<fontfamily><param>Arial</param><smaller><x-tad-smaller>This message
is for the designated recipient only and may contain privileged,
proprietary, or otherwise private information. If you have received it
in error, please notify the sender immediately and delete the
original. Any other use of the email by you is =
prohibited.</x-tad-smaller></smaller></fontfamily></excerpt><excerpt>

</excerpt>=

--Apple-Mail-1-393558136--


<Prev in Thread] Current Thread [Next in Thread>