Bacula-users

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

2010-05-28 03:35:03
Subject: [Bacula-users] 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 09:30:55 +0200
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 had this 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

28-Mai 02:53 bacula-sd JobId 9147: Job write elapsed time = 00:47:33, Transfer rate = 5.544 M Bytes/second
28-Mai 02:53 iq-fd JobId 9147: Fatal error: backup.c:944 Network send error to SD. ERR=Connection reset by peer
28-Mai 02:54 iq-fd JobId 9147: shell command: run ClientAfterJob "/etc/init.d/rc_domino start"
28-Mai 02:54 iq-fd JobId 9147: ClientAfterJob: Switching to notes
28-Mai 02:54 iq-fd JobId 9147: ClientAfterJob: Starting Domino for xLinux (notes)
28-Mai 02:54 iq-fd JobId 9147: ClientAfterJob: done PID is 28278
28-Mai 02:54 iq-fd JobId 9147: ClientAfterJob: ..done
28-Mai 02:54 bacula-dir JobId 9147: Error: Bacula bacula-dir 5.0.1 (24Feb10): 28-Mai-2010 02:54:05
 Build OS:               x86_64-unknown-linux-gnu debian 5.0.4
 JobId:                  9147
 Job:                    iq.2010-05-28_02.05.00_47
 Backup Level:           Differential, since=2010-05-24 02:05:51
 Client:                 "iq-fd" 3.0.0 (06Apr09) x86_64-unknown-linux-gnu,suse,10
 FileSet:                "iq" 2009-07-18 02:05:00
 Pool:                   "Friday" (From Run pool override)
 Catalog:                "MyCatalog" (From Client resource)
 Storage:                "usbchanger1" (From Job resource)
 Scheduled time:         28-Mai-2010 02:05:00
 Start time:             28-Mai-2010 02:05:52
 End time:               28-Mai-2010 02:54:05
 Elapsed time:           48 mins 13 secs
 Priority:               4
 FD Files Written:       363
 SD Files Written:       363
 FD Bytes Written:       15,821,799,152 (15.82 GB)
 SD Bytes Written:       15,819,218,768 (15.81 GB)
 Rate:                   5469.0 KB/s
 Software Compression:   53.3 %
 VSS:                    no
 Encryption:             yes
 Accurate:               no
 Volume name(s):         usbchanger1_0005_0016|usbchanger1_0005_0032|usbchanger1_0005_0033|usbchanger1_0005_0017
 Volume Session Id:      119
 Volume Session Time:    1274770764
 Last Volume Bytes:      1 (1 B)
 Non-fatal FD errors:    0
 SD Errors:              0
 FD termination status:  Error
 SD termination status:  Error
 Termination:            *** Backup Error ***
------------------------------------------------------------------------------

_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users
<Prev in Thread] Current Thread [Next in Thread>