View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000458bareos-coredirectorpublic2015-04-17 10:302023-12-13 13:30
ReporterDmitriy Assigned Topstorz  
PriorityhighSeveritymajorReproducibilityrandom
Status closedResolutionno change required 
Platformx64OSCentOSOS Versionrelease 6.6
Product Version14.2.2 
Summary0000458: During the execution of Job, volume in the status Used mistakenly Recycled.
DescriptionDuring the execution of Job, volume in the status Used mistakenly Recycled.
In bconsole, web interface and database errors are not detected, the job is done with the status OK. Error can be seen in the logs or when restoring data from a failed job.

in log file bareos-dir says: Recycled volume "krus-fs-vol-0176"
15-Апр 00:00 backup-is.enforta.net-dir JobId 8476: Max configured use duration=86,400 sec. exceeded. Marking Volume "krus-fs-vol-0482" as Used.
16-Апр 00:00 backup-is.enforta.net-dir JobId 8530: Recycled volume "krus-fs-vol-0176"

bareos-sd answers: that the other volume is Recycled "krus-fs-vol-0436" (lost data)
16-Апр 00:00 backup-is-sd JobId 8530: Recycled volume "krus-fs-vol-0436" on device "krus-fd-dev" (/extra3/bacula_backup/krus-fs-pool/), all previous data lost.
Additional Information15.04.2015 00:00 running job 8476, return status ОК.

15-Апр 00:00 backup-is.enforta.net-dir JobId 8476: Using Device "krus-fd-dev" to write.
15-Апр 00:00 siebel-oracle-fd JobId 8476: shell command: run ClientBeforeJob "/opt/krus/bin/bacula_pg_backup.sh Incremental start 8476"
15-Апр 00:00 backup-is.enforta.net-dir JobId 8476: Sending Accurate information.
15-Апр 00:00 backup-is.enforta.net-dir JobId 8476: Max configured use duration=86,400 sec. exceeded. Marking Volume "krus-fs-vol-0482" as Used.
15-Апр 00:00 backup-is.enforta.net-dir JobId 8476: Recycled volume "krus-fs-vol-0436"
15-Апр 00:00 backup-is-sd JobId 8476: Recycled volume "krus-fs-vol-0436" on device "krus-fd-dev" (/extra3/bacula_backup/krus-fs-pool/), all previous data lost.
15-Апр 00:01 backup-is-sd JobId 8476: Elapsed time=00:01:05, Transfer rate=85.88 M Bytes/second
  Volume name(s): krus-fs-vol-0436
  Termination: Backup OK

16.04.2015 00:00 Running job 8530, return status ОК, in fact destroyed the data from the volume krus-fs-vol-0436(job 8476)
16-Апр 00:00 backup-is.enforta.net-dir JobId 8530: Using Device "krus-fd-dev" to write.
16-Апр 00:00 backup-is.enforta.net-dir JobId 8530: Max configured use duration=86,400 sec. exceeded. Marking Volume "krus-fs-vol-0436" as Used.
16-Апр 00:00 backup-is.enforta.net-dir JobId 8530: Recycled volume "krus-fs-vol-0176"
16-Апр 00:00 backup-is-sd JobId 8530: Recycled volume "krus-fs-vol-0436" on device "krus-fd-dev" (/extra3/bacula_backup/krus-fs-pool/), all previous data lost.
16-Апр 00:00 backup-is.enforta.net-dir JobId 8530: Max configured use duration=86,400 sec. exceeded. Marking Volume "krus-fs-vol-0436" as Used.
16-Апр 00:01 siebel-oracle-fd JobId 8530: shell command: run ClientAfterJob "/opt/krus/bin/bacula_pg_backup.sh Incremental finish 8530"
16-Апр 00:01 backup-is-sd JobId 8530: Elapsed time=00:01:08, Transfer rate=88.62 M Bytes/second
  Volume name(s): krus-fs-vol-0176|krus-fs-vol-0436
  Termination: Backup OK

in database bareos job 8476 exist on volume krus-fs-vol-0436
bareos=# select m.mediaid, m.volumename from jobmedia jm, media m where jobid=8476 and m.mediaid=jm.mediaid group by m.mediaid, m.volumename;
 mediaid | volumename
---------+------------------
     436 | krus-fs-vol-0436

bareos=# select m.mediaid, m.volumename from jobmedia jm, media m where jobid=8530 and m.mediaid=jm.mediaid group by m.mediaid, m.volumename;
 mediaid | volumename
---------+------------------
     176 | krus-fs-vol-0176
     436 | krus-fs-vol-0436

But viewing volume shows that there is the only job - 8530 (job 8476 absent, restoring data job 8476 on volume krus-fs-vol-0436 failed)
bls -c /home/cruel/bareos-sd.conf -V krus-fs-vol-0436 krus-fd-dev -j
bls: butil.c:298-0 Using device: "krus-fd-dev" for reading.
17-Апр 10:41 bls JobId 0: Ready to read from volume "krus-fs-vol-0436" on device "krus-fd-dev" (/extra3/bacula_backup/krus-fs-pool/).
Volume Record: File:blk=0:226 SessId=409 SessTime=1428425778 JobId=0 DataLen=191
Begin Job Session Record: File:blk=0:64738 SessId=409 SessTime=1428425778 JobId=8530
   Job=siebel-oracle-krus-fs-log-job.2015-04-16_00.00.01_38 Date=16-Апр-2015 00:00:21 Level=I Type=B
End Job Session Record: File:blk=1:1735869214 SessId=409 SessTime=1428425778 JobId=8530
   Date=16-Апр-2015 00:01:29 Level=I Type=B Files=383 Bytes=6,026,360,124 Errors=0 Status=T
17-Апр 10:43 bls JobId 0: End of Volume at file 1 on device "krus-fd-dev" (/extra3/bacula_backup/krus-fs-pool/), Volume "krus-fs-vol-0436"
17-Апр 10:43 bls JobId 0: End of all volumes.

Volume settings:
llist volume=krus-fs-vol-0176
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
          mediaid: 176
       volumename: krus-fs-vol-0176
             slot: 0
           poolid: 13
        mediatype: File
     firstwritten: 2015-04-16 13:20:06
      lastwritten: 2015-04-17 00:00:39
        labeldate: 2015-04-17 00:00:03
          voljobs: 2
         volfiles: 4
        volblocks: 324,295
        volmounts: 6
         volbytes: 20,920,886,821
        volerrors: 0
        volwrites: 1,525,891
volcapacitybytes: 0
        volstatus: Append
          enabled: 1
          recycle: 1
     volretention: 1,209,600
   voluseduration: 86,400
       maxvoljobs: 0
      maxvolfiles: 0
      maxvolbytes: 53,687,091,200
       inchanger: 0
          endfile: 4
         endblock: 3,741,017,636
        labeltype: 0
        storageid: 11
         deviceid: 0
       locationid: 0
     recyclecount: 3
     initialwrite:
    scratchpoolid: 0
    recyclepoolid: 0
          comment:

llist volume=krus-fs-vol-0436
          mediaid: 436
       volumename: krus-fs-vol-0436
             slot: 0
           poolid: 13
        mediatype: File
     firstwritten: 2015-04-15 00:00:19
      lastwritten: 2015-04-16 00:01:29
       labeldate: 2015-04-16 13:14:27
          voljobs: 1
         volfiles: 1
        volblocks: 93,484
        volmounts: 5
         volbytes: 6,030,836,511
        volerrors: 0
        volwrites: 1,295,080
volcapacitybytes: 0
        volstatus: Used
          enabled: 1
          recycle: 1
     volretention: 1,209,600
   voluseduration: 86,400
       maxvoljobs: 0
      maxvolfiles: 0
      maxvolbytes: 53,687,091,200
        inchanger: 0
          endfile: 1
         endblock: 1,735,869,214
        labeltype: 0
        storageid: 11
         deviceid: 0
       locationid: 0
     recyclecount: 1
     initialwrite:
    scratchpoolid: 0
    recyclepoolid: 0
          comment:
TagsNo tags attached.

Activities

Dmitriy

Dmitriy

2015-05-05 08:16

reporter   ~0001708

The problem is repeated and observed in the storage located on the NAS connected via iScsi.

There is a suspicion that the storage falls asleep from inactivity. At the start of the job, NAS awakens after 30 - 60 seconds, and at this time there is a failure.
pstorz

pstorz

2015-05-26 12:06

administrator   ~0001742

Hello,

your last comment seems to show that the problem is caused by your NAS system.

If your NAS system does not behave correctly this is not a bug in bareos.

Do you have more info? Otherwise we will close this bug

Best regards,

Philipp
Dmitriy

Dmitriy

2015-05-26 13:19

reporter   ~0001743

Hello,
I turned off the stop drive on NAS, there is no timeout.
The problem persists.
It may need more information to diagnose the problem?
pstorz

pstorz

2015-09-10 09:22

administrator   ~0001827

Hello,

can you send your configuration please?

Especially the configuration of the Pools would be interesting.

Also, you can run the sd with high debug level (e.g. 500), then it will tell you why it thinks it can recycle a volume.
Dmitriy

Dmitriy

2015-09-16 13:58

reporter   ~0001835

Hello,

I launched bareos-sd demon with debug level 500.
Problem Repeat every 1-2 weeks.
I am waiting for the failure and send the configuration and debug info
Dmitriy

Dmitriy

2015-09-22 10:54

reporter   ~0001848

Hello,

The problem occurs only on volumes in the pool krus-fs-pool when start job siebel-oracle-krus-fs-log-job Type=Incremental

It is a mistake that cleared krus-fs-vol-0187 containing the previous incremental backup

jobid 18190
22-Сен 00:00 backup-is.enforta.net-dir JobId 18190: Recycled volume "krus-fs-vol-0189"
22-Сен 00:00 backup-is-sd JobId 18190: Recycled volume "krus-fs-vol-0187" on device "krus-fd-dev" (/extra3/bacula_backup/krus-fs-pool/), all previous data lost.

Job log
https://drive.google.com/file/d/0BwXK64WOr_77NkcxRXNzNHF6cVk/view?usp=sharing

Full debug bareos-sd level 500
https://drive.google.com/file/d/0BwXK64WOr_77U3JNbV96dmpiMGc/view?usp=sharing

grep 'krus-fs-vol-0187\|krus-fs-vol-0187\|=18190' bareos-sd1.debug >1.log
https://drive.google.com/file/d/0BwXK64WOr_77Y2tFMlZmdWZpQms/view?usp=sharing

Config file
https://drive.google.com/file/d/0BwXK64WOr_77UERqSEl5NzhFV28/view?usp=sharing
bruno-at-bareos

bruno-at-bareos

2023-05-09 16:43

manager   ~0005024

is this still reproducible with recent version 22x
bruno-at-bareos

bruno-at-bareos

2023-12-13 13:30

manager   ~0005624

not return

Issue History

Date Modified Username Field Change
2015-04-17 10:30 Dmitriy New Issue
2015-05-05 08:16 Dmitriy Note Added: 0001708
2015-05-26 12:06 pstorz Note Added: 0001742
2015-05-26 12:06 pstorz Status new => feedback
2015-05-26 13:19 Dmitriy Note Added: 0001743
2015-05-26 13:19 Dmitriy Status feedback => new
2015-09-10 09:22 pstorz Note Added: 0001827
2015-09-10 09:23 pstorz Assigned To => pstorz
2015-09-10 09:23 pstorz Status new => feedback
2015-09-16 13:58 Dmitriy Note Added: 0001835
2015-09-16 13:58 Dmitriy Status feedback => assigned
2015-09-22 10:54 Dmitriy Note Added: 0001848
2023-05-09 16:43 bruno-at-bareos Status assigned => feedback
2023-05-09 16:43 bruno-at-bareos Note Added: 0005024
2023-12-13 13:30 bruno-at-bareos Status feedback => closed
2023-12-13 13:30 bruno-at-bareos Resolution open => no change required
2023-12-13 13:30 bruno-at-bareos Note Added: 0005624