Bacula-users
[Top] [All Lists]
<prev [Date] next>
[Advanced]
 <prev [Thread] next>

[Bacula-users] Antwort: Re: backup failed, network problems, vchanger or bacula?

2010-05-28 09:10:37
Subject: [Bacula-users] Antwort: Re: backup failed, network problems, vchanger or bacula?
From: C.Keschnat AT internet-mit-iQ DOT de
To: bacula-users AT lists.sourceforge DOT net
Date: Fri, 28 May 2010 15:07:47 +0200
John Drescher <drescherjm AT gmail DOT com> wrote on 28.05.2010 13:53:46:

> John Drescher <drescherjm AT gmail DOT com>
> 28.05.2010 13:53
>
> An
>
> C.Keschnat AT internet-mit-iq DOT de
>
> Kopie
>
> bacula-users AT lists.sourceforge DOT net
>
> Thema
>
> Re: [Bacula-users] backup failed, network problems, vchanger or  bacula?
>
> 2010/5/28  <C.Keschnat AT internet-mit-iq DOT de>:
> > Today our backups failed. It seemed to run fine until some point, then it
> > stopped with a changer error. There was also this error:
> > ptrace: Operation not permitted.
> > /home/bacula/working/19031: No such file or directory.
> > $1 = 0
> > /home/bacula/etc/btraceback.gdb:2: Error in sourced command file:
> > No symbol "exename" in current context.
> >
> > But I don't know if that is related.
> >
> > All the Joboutputs have these lines in them:
> > 28-Mai 02:53 bacula-sd JobId 9147: 3301 Issuing autochanger "loaded? drive
> > 0" command.
> > 28-Mai 02:53 bacula-sd JobId 9147: 3991 Bad autochanger "loaded? drive 0"
> > command: ERR=Child exited with code 1.
> > Results=Could not write loaded0 file on /mnt/usbchanger1/mag
> >
> > The first job wrote some data and also had this lines in the output:
> > 28-Mai 02:53 iq-fd JobId 9147: Fatal error: backup.c:944 Network send error
> > to SD. ERR=Connection reset by peer
> >
> > Seems like there was a problem with the network. The external HDD is mounted
> > through iSCSI on the server. When I came to work this morning though I could
> > touch and delete files without problems so the iSCSI connection was still
> > there. Could small network problems cause vchanger/bacula to stop working?
> > I'd like to find out if the problem is bacula or vchanger related. I know
> > that probably noone is using vchanger with iSCSI but I hope someone might
> > have an idea on how to solve this (it is not the first time we hadthis kind
> > of problem).
> > This is bacula 5.0.1 (clients 3.0.0) and vchanger 0.8.2.
> >
> > Here is the full output of the first job that ran:
> >
> > 28-Mai 02:05 bacula-dir JobId 9147: Start Backup JobId 9147,
> > Job=iq.2010-05-28_02.05.00_47
> > 28-Mai 02:05 bacula-dir JobId 9147: Using Device "usb-changer-1-drive-0"
> > 28-Mai 02:05 iq-fd JobId 9147: shell command: run ClientBeforeJob
> > "/etc/init.d/rc_domino stop"
> > 28-Mai 02:05 iq-fd JobId 9147: ClientBeforeJob: Switching to notes
> > 28-Mai 02:05 iq-fd JobId 9147: ClientBeforeJob: Stopping Domino for xLinux
> > (notes)
> > 28-Mai 02:05 iq-fd JobId 9147: ClientBeforeJob:  ... waiting for shutdown to
> > complete
> > 28-Mai 02:05 iq-fd JobId 9147: ClientBeforeJob:  ... waiting 10 seconds
> > 28-Mai 02:05 iq-fd JobId 9147: ClientBeforeJob:  ... waiting 20 seconds
> > 28-Mai 02:05 iq-fd JobId 9147: ClientBeforeJob:  ... waiting 30 seconds
> > 28-Mai 02:05 iq-fd JobId 9147: ClientBeforeJob:  ... waiting 40 seconds
> > 28-Mai 02:05 iq-fd JobId 9147: ClientBeforeJob:  ... waiting 50 seconds
> > 28-Mai 02:05 iq-fd JobId 9147: ClientBeforeJob: ..done
> > 28-Mai 02:05 iq-fd JobId 9147: ClientBeforeJob: Domino for xLinux (notes)
> > shutdown completed
> > 28-Mai 02:05 bacula-sd JobId 9147: 3307 Issuing autochanger "unload slot 15,
> > drive 0" command.
> > 28-Mai 02:05 bacula-sd JobId 9147: 3304 Issuing autochanger "load slot 16,
> > drive 0" command.
> > 28-Mai 02:05 bacula-sd JobId 9147: 3305 Autochanger "load slot 16,drive 0",
> > status is OK.
> > 28-Mai 02:05 bacula-sd JobId 9147: Volume "usbchanger1_0005_0016" previously
> > written, moving to end of data.
> > 28-Mai 02:05 bacula-sd JobId 9147: Ready to append to end of Volume
> > "usbchanger1_0005_0016" size=2781850256
> > 28-Mai 02:12 bacula-sd JobId 9147: User defined maximum volume capacity
> > 4,831,838,208 exceeded on device "usb-changer-1-drive-0"
> > (/home/bacula/working/usbchanger1/0/drive0).
> > 28-Mai 02:12 bacula-sd JobId 9147: End of medium on Volume
> > "usbchanger1_0005_0016" Bytes=4,831,783,484 Blocks=74,900 at 28-Mai-2010
> > 02:12.
> > 28-Mai 02:12 bacula-sd JobId 9147: 3307 Issuing autochanger "unload slot 16,
> > drive 0" command.
> > 28-Mai 02:12 bacula-dir JobId 9147: There are no more Jobs associated with
> > Volume "usbchanger1_0005_0032". Marking it purged.
> > 28-Mai 02:12 bacula-dir JobId 9147: All records pruned from Volume
> > "usbchanger1_0005_0032"; marking it "Purged"
> > 28-Mai 02:12 bacula-dir JobId 9147: Recycled volume "usbchanger1_0005_0032"
> > 28-Mai 02:12 bacula-sd JobId 9147: 3301 Issuing autochanger "loaded? drive
> > 0" command.
> > 28-Mai 02:12 bacula-sd JobId 9147: 3302 Autochanger "loaded? drive 0",
> > result: nothing loaded.
> > 28-Mai 02:12 bacula-sd JobId 9147: 3304 Issuing autochanger "load slot 32,
> > drive 0" command.
> > 28-Mai 02:12 bacula-sd JobId 9147: 3305 Autochanger "load slot 32,drive 0",
> > status is OK.
> > 28-Mai 02:12 bacula-sd JobId 9147: Recycled volume "usbchanger1_0005_0032"
> > on device "usb-changer-1-drive-0"
> > (/home/bacula/working/usbchanger1/0/drive0), all previous data lost.
> > 28-Mai 02:12 bacula-sd JobId 9147: New volume "usbchanger1_0005_0032"
> > mounted on device "usb-changer-1-drive-0"
> > (/home/bacula/working/usbchanger1/0/drive0) at 28-Mai-2010 02:12.
> > 28-Mai 02:27 bacula-sd JobId 9147: User defined maximum volume capacity
> > 4,831,838,208 exceeded on device "usb-changer-1-drive-0"
> > (/home/bacula/working/usbchanger1/0/drive0).
> > 28-Mai 02:27 bacula-sd JobId 9147: End of medium on Volume
> > "usbchanger1_0005_0032" Bytes=4,831,819,893 Blocks=74,898 at 28-Mai-2010
> > 02:27.
> > 28-Mai 02:27 bacula-sd JobId 9147: 3307 Issuing autochanger "unload slot 32,
> > drive 0" command.
> > 28-Mai 02:27 bacula-dir JobId 9147: There are no more Jobs associated with
> > Volume "usbchanger1_0005_0033". Marking it purged.
> > 28-Mai 02:27 bacula-dir JobId 9147: All records pruned from Volume
> > "usbchanger1_0005_0033"; marking it "Purged"
> > 28-Mai 02:27 bacula-dir JobId 9147: Recycled volume "usbchanger1_0005_0033"
> > 28-Mai 02:27 bacula-sd JobId 9147: 3301 Issuing autochanger "loaded? drive
> > 0" command.
> > 28-Mai 02:27 bacula-sd JobId 9147: 3302 Autochanger "loaded? drive 0",
> > result: nothing loaded.
> > 28-Mai 02:27 bacula-sd JobId 9147: 3304 Issuing autochanger "load slot 33,
> > drive 0" command.
> > 28-Mai 02:27 bacula-sd JobId 9147: 3305 Autochanger "load slot 33,drive 0",
> > status is OK.
> > 28-Mai 02:27 bacula-sd JobId 9147: Recycled volume "usbchanger1_0005_0033"
> > on device "usb-changer-1-drive-0"
> > (/home/bacula/working/usbchanger1/0/drive0), all previous data lost.
> > 28-Mai 02:27 bacula-sd JobId 9147: New volume "usbchanger1_0005_0033"
> > mounted on device "usb-changer-1-drive-0"
> > (/home/bacula/working/usbchanger1/0/drive0) at 28-Mai-2010 02:27.
> > 28-Mai 02:40 bacula-sd JobId 9147: End of Volume "usbchanger1_0005_0033" at
> > 0:4120639609 on device "usb-changer-1-drive-0"
> > (/home/bacula/working/usbchanger1/0/drive0). Write of 64512 bytes got 55174.
> > 28-Mai 02:40 bacula-sd JobId 9147: End of medium on Volume
> > "usbchanger1_0005_0033" Bytes=4,120,639,610 Blocks=63,874 at 28-Mai-2010
> > 02:40.
> > 28-Mai 02:40 bacula-sd JobId 9147: 3307 Issuing autochanger "unload slot 33,
> > drive 0" command.
> > 28-Mai 02:40 bacula-dir JobId 9147: There are no more Jobs associated with
> > Volume "usbchanger1_0005_0017". Marking it purged.
> > 28-Mai 02:40 bacula-dir JobId 9147: All records pruned from Volume
> > "usbchanger1_0005_0017"; marking it "Purged"
> > 28-Mai 02:40 bacula-dir JobId 9147: Recycled volume "usbchanger1_0005_0017"
> > 28-Mai 02:40 bacula-sd JobId 9147: 3301 Issuing autochanger "loaded? drive
> > 0" command.
> > 28-Mai 02:40 bacula-sd JobId 9147: 3302 Autochanger "loaded? drive 0",
> > result: nothing loaded.
> > 28-Mai 02:40 bacula-sd JobId 9147: 3304 Issuing autochanger "load slot 17,
> > drive 0" command.
> > 28-Mai 02:40 bacula-sd JobId 9147: 3305 Autochanger "load slot 17,drive 0",
> > status is OK.
> > 28-Mai 02:41 bacula-sd JobId 9147: Recycled volume "usbchanger1_0005_0017"
> > on device "usb-changer-1-drive-0"
> > (/home/bacula/working/usbchanger1/0/drive0), all previous data lost.
> > 28-Mai 02:41 bacula-sd JobId 9147: New volume "usbchanger1_0005_0017"
> > mounted on device "usb-changer-1-drive-0"
> > (/home/bacula/working/usbchanger1/0/drive0) at 28-Mai-2010 02:41.
> > 28-Mai 02:53 bacula-sd JobId 9147: User defined maximum volume capacity
> > 4,831,838,208 exceeded on device "usb-changer-1-drive-0"
> > (/home/bacula/working/usbchanger1/0/drive0).
> > 28-Mai 02:53 bacula-sd JobId 9147: End of medium on Volume
> > "usbchanger1_0005_0017" Bytes=4,831,819,881 Blocks=74,898 at 28-Mai-2010
> > 02:53.
> > 28-Mai 02:53 bacula-sd JobId 9147: 3307 Issuing autochanger "unload slot 17,
> > drive 0" command.
> > 28-Mai 02:53 bacula-sd JobId 9147: 3995 Bad autochanger "unload slot 17,
> > drive 0": ERR=Child exited with code 1
> > Results=Could not write loaded0 file on /mnt/usbchanger1/mag
> >
> > 28-Mai 02:53 bacula-dir JobId 9147: There are no more Jobs associated with
> > Volume "usbchanger1_0005_0031". Marking it purged.
> > 28-Mai 02:53 bacula-dir JobId 9147: All records pruned from Volume
> > "usbchanger1_0005_0031"; marking it "Purged"
> > 28-Mai 02:53 bacula-dir JobId 9147: Recycled volume "usbchanger1_0005_0031"
> > 28-Mai 02:53 bacula-sd JobId 9147: 3301 Issuing autochanger "loaded? drive
> > 0" command.
> > 28-Mai 02:53 bacula-sd JobId 9147: 3991 Bad autochanger "loaded? drive 0"
> > command: ERR=Child exited with code 1.
> > Results=Could not write loaded0 file on /mnt/usbchanger1/mag
> >
> > 28-Mai 02:53 bacula-sd JobId 9147: 3301 Issuing autochanger "loaded? drive
> > 0" command.
> > 28-Mai 02:53 bacula-sd JobId 9147: 3991 Bad autochanger "loaded? drive 0"
> > command: ERR=Child exited with code 1.
> > Results=Could not write loaded0 file on /mnt/usbchanger1/mag
> >
> > 28-Mai 02:53 bacula-sd JobId 9147: 3304 Issuing autochanger "load slot 31,
> > drive 0" command.
> > 28-Mai 02:53 bacula-sd JobId 9147: Fatal error: 3992 Bad autochanger "load
> > slot 31, drive 0": ERR=Child exited with code 1.
> > Results=Could not write loaded0 file on /mnt/usbchanger1/mag
> >
>
> The problem looks to be with vchanger. Did you run out of space?
>
> John
>
> ------------------------------------------------------------------------------
Probably not, unless vchanger uses some temporary space on the disk. There a 39 volumes with Maximum Volume Bytes = 4608 MB so that is about 175.5 GB. The disk is187 GB (df -h output). I always copy the bacula configuration and a catalog dump to the disk, but that are just 2 GB so there should be 9 GB free. Also before the backup all volumes were fully written and then recycled.
"Results=Could not write loaded0 file on /mnt/usbchanger1/mag" leads me to believe you are right, but there is also still "iq-fd JobId 9147: Fatal error: backup.c:944 Network send error to SD. ERR=Connection reset by peer"

I will try to monitor if there are some space related issues.

Chris
------------------------------------------------------------------------------


_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users
[More with this subject...]
<Prev in Thread] Current Thread [Next in Thread>
Previous by Date:  Re: [Bacula-users] [Bacula-devel] bconsole scripting, Olaf Zevenboom
Next by Date:  Re: [Bacula-users] Bacula tape format vs. rsync on deduplicated file systems, Robert LeBlanc
Previous by Thread:  Re: [Bacula-users] backup failed, network problems, vchanger or bacula?, John Drescher
Next by Thread:  [Bacula-users] How to find all file .avi from full tape, Simone Martina
Indexes:  [Date] [Thread] [Top] [All Lists]