View Issue Details

IDProjectCategoryView StatusLast Update
0000933bareos-core[All Projects] directorpublic2019-07-29 17:31
ReporterhostedpowerAssigned To 
PriorityhighSeveritymajorReproducibilityalways
Status acknowledgedResolutionopen 
PlatformLinuxOSDebianOS Version9
Product Version16.2.7 
Target VersionFixed in Version 
Summary0000933: Fatal error: fd_plugins.c:1237 Unbalanced call to createFile=0 0
Description2018-03-22 12:27:28 example-dir JobId 15968: Error: Bareos example-dir 16.2.7 (09Oct17):
 Build OS: x86_64-pc-linux-gnu debian Debian GNU/Linux 8.0 (jessie)
 JobId: 15968
 Job: RestoreFiles.2018-03-22_12.26.32_04
 Restore Client: customer.xxx.com
 Start time: 22-Mar-2018 12:26:34
 End time: 22-Mar-2018 12:27:28
 Elapsed time: 54 secs
 Files Expected: 126,634
 Files Restored: 126,601
 Bytes Restored: 4,869,318,236
 Rate: 90172.6 KB/s
 FD Errors: 1
 FD termination status: Fatal Error
 SD termination status: OK
 Termination: *** Restore Error ***

 
2018-03-22 12:27:28 example-dir JobId 15968: Begin pruning Files.
 
2018-03-22 12:27:28 example-dir JobId 15968: No Files found to prune.
 
2018-03-22 12:27:28 example-dir JobId 15968: End auto prune.

 
2018-03-22 12:27:27 bareos-sd JobId 15968: End of Volume at file 2 on device "example-incr" (/home/example/bareos), Volume "vol-incr-0447"
 
2018-03-22 12:27:27 bareos-sd JobId 15968: Ready to read from volume "vol-cons-0486" on device "example-incr" (/home/example/bareos).
 
2018-03-22 12:27:27 bareos-sd JobId 15968: Forward spacing Volume "vol-cons-0486" to file:block 0:218.
 
2018-03-22 12:27:27 customer.xxx.com JobId 15968: Fatal error: fd_plugins.c:1237 Unbalanced call to createFile=0 0
 
2018-03-22 12:27:26 bareos-sd JobId 15968: End of Volume at file 8 on device "example-incr" (/home/example/bareos), Volume "vol-cons-0513"
 
2018-03-22 12:27:26 bareos-sd JobId 15968: Ready to read from volume "vol-incr-0447" on device "example-incr" (/home/example/bareos).
 
2018-03-22 12:27:26 bareos-sd JobId 15968: Forward spacing Volume "vol-incr-0447" to file:block 2:769145852.
 
2018-03-22 12:26:38 bareos-sd JobId 15968: End of Volume at file 2 on device "example-incr" (/home/example/bareos), Volume "vol-incr-0446"
 
2018-03-22 12:26:38 bareos-sd JobId 15968: Ready to read from volume "vol-cons-0513" on device "example-incr" (/home/example/bareos).
 
2018-03-22 12:26:38 bareos-sd JobId 15968: Forward spacing Volume "vol-cons-0513" to file:block 7:417218068.
 
2018-03-22 12:26:37 bareos-sd JobId 15968: End of Volume at file 2 on device "example-incr" (/home/example/bareos), Volume "vol-incr-0456"
 
2018-03-22 12:26:37 bareos-sd JobId 15968: Ready to read from volume "vol-incr-0446" on device "example-incr" (/home/example/bareos).
 
2018-03-22 12:26:37 bareos-sd JobId 15968: Forward spacing Volume "vol-incr-0446" to file:block 2:786923100.
 
2018-03-22 12:26:36 bareos-sd JobId 15968: End of Volume at file 2 on device "example-incr" (/home/example/bareos), Volume "vol-incr-0423"
 
2018-03-22 12:26:36 bareos-sd JobId 15968: Ready to read from volume "vol-incr-0456" on device "example-incr" (/home/example/bareos).
 
2018-03-22 12:26:36 bareos-sd JobId 15968: Forward spacing Volume "vol-incr-0456" to file:block 2:691729567.
 
2018-03-22 12:26:35 bareos-sd JobId 15968: Ready to read from volume "vol-incr-0423" on device "example-incr" (/home/example/bareos).
 
2018-03-22 12:26:35 bareos-sd JobId 15968: Forward spacing Volume "vol-incr-0423" to file:block 2:606078578.
 
2018-03-22 12:26:34 example-dir JobId 15968: Start Restore Job RestoreFiles.2018-03-22_12.26.32_04
 
2018-03-22 12:26:34 example-dir JobId 15968: Using Device "example-incr" to read.
Steps To ReproduceRestore files from an always incremental schedule, including a mysql backup

We tried separate restore afterwards and this works without errors (so first restore of files and than a separate restore job for the database)
TagsNo tags attached.
bareos-master: impact
bareos-master: action
bareos-18.2: impact
bareos-18.2: action
bareos-17.2: impact
bareos-17.2: action
bareos-16.2: impact
bareos-16.2: action
bareos-15.2: impact
bareos-15.2: action
bareos-14.2: impact
bareos-14.2: action
bareos-13.2: impact
bareos-13.2: action
bareos-12.4: impact
bareos-12.4: action

Activities

joergs

joergs

2018-04-05 12:54

administrator   ~0002960

So, what plugings have you configured? This error should only occur, if a plugin is used.
hostedpower

hostedpower

2018-04-05 13:44

reporter   ~0002964

Hello Joergs,

We use the MySQL plugin of course :)
joergs

joergs

2018-04-05 16:47

administrator   ~0002965

Well, there are still multiple MySQL plugins and different possible configurations.
hostedpower

hostedpower

2018-04-05 16:50

reporter   ~0002966

We used this install procedure:


cd /tmp
git clone https://github.com/bareos/bareos-contrib
cp -R ./bareos-contrib/fd-plugins/mysql-python/*.py /usr/lib/bareos/plugins/
rm -rf bareos-contrib/
service bareos-fd restart

It's strange that seperate restores work perfectly, it's only when we combine SQL dump file restore & regular files we run into issues.

Please let me know which info exactly you need if you need anything else!
hostedpower

hostedpower

2019-07-29 12:03

reporter   ~0003530

Today this is still an issue..

If we restore MySQL database and files together it goes wrong :(



2019-07-29 11:59:57 xxxx JobId 88755: Fatal error: filed/fd_plugins.cc:1247 Unbalanced call to createFile=0 0
 
2019-07-29 11:59:57 backupxxx JobId 88755: Error: lib/bsock_tcp.cc:417 Wrote 29242 bytes to client:94.237.42.21:9103, but only 0 accepted.
 
2019-07-29 11:59:57 backupxxx JobId 88755: Fatal error: stored/read.cc:164 Error sending to File daemon. ERR=Connection reset by peer
 
2019-07-29 11:59:57 backupxxx JobId 88755: Error: lib/bsock_tcp.cc:457 Socket has errors=1 on call to client:94.237.42.21:9103
 
2019-07-29 11:59:57 backupxxx JobId 88755: Releasing device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:57 director JobId 88755: Max configured use duration=82,800 sec. exceeded. Marking Volume "vol-cons-3373" as Used.
 
2019-07-29 11:59:57 director JobId 88755: Error: Bareos director 18.2.6 (13Feb19):
 Build OS: Linux-4.4.92-6.18-default debian Debian GNU/Linux 9.7 (stretch)
 JobId: 88755
 Job: RestoreFiles.2019-07-29_11.09.05_18
 Restore Client: xxxxx
 Start time: 29-Jul-2019 11:58:44
 End time: 29-Jul-2019 11:59:57
 Elapsed time: 1 min 13 secs
 Files Expected: 186,501
 Files Restored: 15,767
 Bytes Restored: 5,625,032,491
 Rate: 77055.2 KB/s
 FD Errors: 1
 FD termination status: Fatal Error
 SD termination status: Fatal Error
 Bareos binary info: official Bareos subscription
 Termination: *** Restore Error ***

 
2019-07-29 11:59:57 director JobId 88755: Begin pruning Files.
 
2019-07-29 11:59:57 director JobId 88755: No Files found to prune.
 
2019-07-29 11:59:57 director JobId 88755: End auto prune.

 
2019-07-29 11:59:56 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3338"
 
2019-07-29 11:59:56 backupxxx JobId 88755: Ready to read from volume "vol-cons-3373" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:56 backupxxx JobId 88755: Forward spacing Volume "vol-cons-3373" to file:block 0:241.
 
2019-07-29 11:59:53 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3325"
 
2019-07-29 11:59:53 backupxxx JobId 88755: Ready to read from volume "vol-incr-3338" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:53 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3338" to file:block 0:241.
 
2019-07-29 11:59:51 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3314"
 
2019-07-29 11:59:51 backupxxx JobId 88755: Ready to read from volume "vol-incr-3325" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:51 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3325" to file:block 0:241.
 
2019-07-29 11:59:49 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3307"
 
2019-07-29 11:59:49 backupxxx JobId 88755: Ready to read from volume "vol-incr-3314" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:49 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3314" to file:block 0:241.
 
2019-07-29 11:59:40 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3283"
 
2019-07-29 11:59:40 backupxxx JobId 88755: Ready to read from volume "vol-incr-3295" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:40 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3295" to file:block 0:241.
 
2019-07-29 11:59:40 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3295"
 
2019-07-29 11:59:40 backupxxx JobId 88755: Ready to read from volume "vol-incr-3307" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:40 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3307" to file:block 0:241.
 
2019-07-29 11:59:30 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3276"
 
2019-07-29 11:59:30 backupxxx JobId 88755: Ready to read from volume "vol-incr-3283" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:30 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3283" to file:block 0:241.
 
2019-07-29 11:59:02 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3265"
 
2019-07-29 11:59:02 backupxxx JobId 88755: Ready to read from volume "vol-incr-3276" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:02 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3276" to file:block 0:241.
 
2019-07-29 11:59:01 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3258"
 
2019-07-29 11:59:01 backupxxx JobId 88755: Ready to read from volume "vol-incr-3265" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:01 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3265" to file:block 0:241.
 
2019-07-29 11:59:00 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3252"
 
2019-07-29 11:59:00 backupxxx JobId 88755: Ready to read from volume "vol-incr-3258" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:59:00 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3258" to file:block 0:241.
 
2019-07-29 11:58:57 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3244"
 
2019-07-29 11:58:57 backupxxx JobId 88755: Ready to read from volume "vol-incr-3252" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:58:57 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3252" to file:block 0:241.
 
2019-07-29 11:58:56 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3230"
 
2019-07-29 11:58:56 backupxxx JobId 88755: Ready to read from volume "vol-incr-3244" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:58:56 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3244" to file:block 0:241.
 
2019-07-29 11:58:54 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3224"
 
2019-07-29 11:58:54 backupxxx JobId 88755: Ready to read from volume "vol-incr-3230" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:58:54 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3230" to file:block 0:241.
 
2019-07-29 11:58:51 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3218"
 
2019-07-29 11:58:51 backupxxx JobId 88755: Ready to read from volume "vol-incr-3224" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:58:51 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3224" to file:block 0:241.
 
2019-07-29 11:58:49 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3212"
 
2019-07-29 11:58:49 backupxxx JobId 88755: Ready to read from volume "vol-incr-3218" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:58:49 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3218" to file:block 0:241.
 
2019-07-29 11:58:48 backupxxx JobId 88755: End of Volume at file 0 on device "serverxx-incr" (/home/serverxx/bareos), Volume "vol-incr-3364"
 
2019-07-29 11:58:48 backupxxx JobId 88755: Ready to read from volume "vol-incr-3212" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:58:48 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3212" to file:block 0:241.
 
2019-07-29 11:58:47 backupxxx JobId 88755: Ready to read from volume "vol-incr-3364" on device "serverxx-incr" (/home/serverxx/bareos).
 
2019-07-29 11:58:47 backupxxx JobId 88755: Forward spacing Volume "vol-incr-3364" to file:block 0:241.
 
2019-07-29 11:58:46 xxxx JobId 88755: Connected Storage daemon at backupxxx:9103, encryption: PSK-AES256-CBC-SHA
 
2019-07-29 11:58:44 director JobId 88755: Start Restore Job RestoreFiles.2019-07-29_11.09.05_18
 
2019-07-29 11:58:44 director JobId 88755: Connected Storage daemon at backupxxx:9103, encryption: ECDHE-PSK-CHACHA20-POLY1305
 
2019-07-29 11:58:44 director JobId 88755: Using Device "serverxx-incr" to read.
 
2019-07-29 11:58:44 director JobId 88755: Connected Client: xxxx at xxxx:9102, encryption: PSK-AES256-CBC-SHA
 
2019-07-29 11:58:44 director JobId 88755: Handshake: Immediate TLS
2019-07-29 11:58:44 director JobId 88755: Encryption: PSK-AES256-CBC-SHA
hostedpower

hostedpower

2019-07-29 17:31

reporter   ~0003532

to be clear.

Restore together, result:

Files: Not complete
MySQL db: restore looks ok

Restore Files and db , both in seperate job:

Files: OK
MySQL db: OK

Issue History

Date Modified Username Field Change
2018-03-22 12:44 hostedpower New Issue
2018-04-05 12:54 joergs Note Added: 0002960
2018-04-05 12:54 joergs Status new => feedback
2018-04-05 13:44 hostedpower Note Added: 0002964
2018-04-05 13:44 hostedpower Status feedback => new
2018-04-05 16:47 joergs Note Added: 0002965
2018-04-05 16:47 joergs Status new => feedback
2018-04-05 16:50 hostedpower Note Added: 0002966
2018-04-05 16:50 hostedpower Status feedback => new
2019-07-29 12:03 hostedpower Note Added: 0003530
2019-07-29 17:30 arogge Status new => acknowledged
2019-07-29 17:31 hostedpower Note Added: 0003532