You are not logged in.
- Topics: Active | Unanswered
#1 2016-01-03 19:37:55
- rwd
- Member
- Registered: 2009-02-08
- Posts: 664
rdiff-backup segfault after upgrade to librsync-2.0.0-1
After upgrading librsync from 1.0.0-1 2.0.0-1 on my 32bit server, rdiff-backup (1.2.8-7) segfaults when making a backup. Downgrading librsync back to 1.0.0-1 solved the segfaults, but which package should I report a bug for: rdiff-backup or librsync? I don't understand the stack trace below well enough to decide which is the culprit.
The problem only (and consistently ) happens when I issue a particular backup command, doing a backup of my whole system, and not when testing with some random folders. So I guess the particularities of my system backup archive and/or backed up files also trigger this error. Below are various logs rdiff-backup segfaulting using the same rdiff-backup command although the strace log is from a later crash.
journald output:
Jan 03 18:43:17 arch-server mysqld[7119]: 2016-01-03 18:43:17 3046475584 [Note] InnoDB: Waiting for purge to start
Jan 03 18:43:17 arch-server mysqld[7119]: 2016-01-03 18:43:17 3046475584 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.26-76.0 started; log sequence number 9301768744
Jan 03 18:43:17 arch-server systemd-coredump[7114]: Process 7110 (rdiff-backup) of user 0 dumped core.
Stack trace of thread 7110:
#0 0x00000000b6b873fd rs_search_for_block (librsync.so.2)
#1 0x00000000b6b83cfc n/a (librsync.so.2)
#2 0x00000000b6b84bd4 rs_job_iter (librsync.so.2)
#3 0x00000000b6d39fbc n/a (_librsync.so)
#4 0x00000000b75fbb55 PyCFunction_Call (libpython2.7.so.1.0)
#5 0x00000000b765e777 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#6 0x00000000b765dd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#7 0x00000000b7661625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#8 0x00000000b765dc31 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#9 0x00000000b765dd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#10 0x00000000b7661625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#11 0x00000000b765dc31 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#12 0x00000000b7661625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#13 0x00000000b765dc31 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#14 0x00000000b765dd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#15 0x00000000b7661625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#16 0x00000000b75e480a function_call (libpython2.7.so.1.0)
#17 0x00000000b75baf3b PyObject_Call (libpython2.7.so.1.0)
#18 0x00000000b7659280 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#19 0x00000000b7661625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#20 0x00000000b765dc31 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#21 0x00000000b7661625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#22 0x00000000b75e480a function_call (libpython2.7.so.1.0)
#23 0x00000000b75baf3b PyObject_Call (libpython2.7.so.1.0)
#24 0x00000000b7659280 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#25 0x00000000b7661625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#26 0x00000000b75e480a function_call (libpython2.7.so.1.0)
#27 0x00000000b75baf3b PyObject_Call (libpython2.7.so.1.0)
#28 0x00000000b75cb90b instancemethod_call (libpython2.7.so.1.0)
#29 0x00000000b75baf3b PyObject_Call (libpython2.7.so.1.0)
#30 0x00000000b75c7453 instance_call (libpython2.7.so.1.0)
#31 0x00000000b75baf3b PyObject_Call (libpython2.7.so.1.0)
#32 0x00000000b765d7bc PyEval_EvalFrameEx (libpython2.7.so.1.0)
#33 0x00000000b765dd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#34 0x00000000b765dd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#35 0x00000000b765dd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#36 0x00000000b765dd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#37 0x00000000b765dd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#38 0x00000000b765dd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#39 0x00000000b7661625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#40 0x00000000b766176b PyEval_EvalCode (libpython2.7.so.1.0)
#41 0x00000000b767bad6 run_mod (libpython2.7.so.1.0)
#42 0x00000000b767cf1b PyRun_FileExFlags (libpython2.7.so.1.0)
#43 0x00000000b767e3a0 PyRun_SimpleFileExFlags (libpython2.7.so.1.0)
#44 0x00000000b767e8e5 PyRun_AnyFileExFlags (libpython2.7.so.1.0)
#45 0x00000000b7691d82 Py_Main (libpython2.7.so.1.0)
#46 0x0000000008048594 main (python2.7)
#47 0x00000000b73cd497 __libc_start_main (libc.so.6)
#48 0x00000000080485c2 _start (python2.7)
Jan 03 18:43:18 arch-server mysqld[7119]: 2016-01-03 18:43:18 2371873600 [Note] InnoDB: Dumping buffer pool(s) not yet started
Jan 03 18:43:18 arch-server mysqld[7119]: 2016-01-03 18:43:18 3046475584 [Note] Plugin 'FEEDBACK' is disabled.
Jan 03 18:43:18 arch-server mysqld[7119]: 2016-01-03 18:43:18 3046475584 [Note] Server socket created on IP: '127.0.0.1'.
Jan 03 18:43:18 arch-server mysqld[7119]: 2016-01-03 18:43:18 3046475584 [Note] /usr/bin/mysqld: ready for connections.output by rdiff-backup:
Sun Jan 3 18:43:10 2016 Processing changed file srv/mysql/ibdata1
Sun Jan 3 18:43:10 2016 Writing file object to /mnt/backup/backups/arch-server-data/srv/mysql/rdiff-backup.tmp.8
Sun Jan 3 18:43:14 2016 Copying attributes from ('srv', 'mysql', 'ibdata1') to /mnt/backup/backups/arch-server-data/srv/mysql/rdiff-backup.tmp.8
Sun Jan 3 18:43:14 2016 Setting time of /mnt/backup/backups/arch-server-data/srv/mysql/rdiff-backup.tmp.8 to 1451842954
Sun Jan 3 18:43:14 2016 Incrementing mirror file /mnt/backup/backups/arch-server-data/srv/mysql/ibdata1
Sun Jan 3 18:43:14 2016 Writing delta /mnt/backup/backups/arch-server-data/srv/mysql/rdiff-backup.tmp.8 from /mnt/backup/backups/arch-server-data/srv/mysql/ibdata1 -> /mnt/backup/backups/arch-server-data/rdiff-backup-data/increments/srv/mysql/ibdata1.2016-01-03T18:11:47+01:00.diff.gz
Sun Jan 3 18:43:14 2016 Getting signature of srv/mysql/rdiff-backup.tmp.8 with blocksize 8800
Sun Jan 3 18:43:15 2016 Writing file object to /mnt/backup/backups/arch-server-data/rdiff-backup-data/increments/srv/mysql/ibdata1.2016-01-03T18:11:47+01:00.diff.gz
./test.sh: line 54: 7110 Segmentation fault (core dumped) /usr/bin/rdiff-backup --terminal-verbosity 9 --verbosity 9 --exclude-sockets --exclude /mnt/data/lost+found --exclude /mnt/data/home/*/.cache --exclude /mnt/data/home/*/.local/share/Trash/files --exclude /mnt/data/home/*/.Trash --exclude /mnt/data/home/*/.last few lines of a log made with strace -Ff -tt <program> <arguments> 2>&1 | tee errorlog.txt :
19:20:54.969647 read(9, "9Z5K\0\0\4\f\0\0\0\0\0\0\0\0\0\0\0\2*m\376W\0\2\0\0\0\0\0\0"..., 65536) = 65536
19:20:54.973357 read(9, "\331\262\267\25\0\0\4\20\0\0\0\0\0\0\0\0\0\0\0\2*k\320\266\0\2\0\0\0\0\0\0"..., 65536) = 65536
19:20:54.977508 read(9, ")5px\0\0\4\24\0\0\0\0\0\0\0\0\0\0\0\2*mA\216\0\2\0\0\0\0\0\0"..., 65536) = 65536
19:20:54.981676 read(9, "\217\217\2\373\0\0\4\30\0\0\0\0\0\0\0\0\0\0\0\2*n\23\32\0\2\0\0\0\0\0\0"..., 65536) = 65536
19:20:54.987203 --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x9304644} ---
19:20:55.223726 +++ killed by SIGSEGV (core dumped) +++update:
I see that in the crash at 18:43:15 mysqld is starting up while rdiff-backup is reading its data files. After making sure mysqld is stopped before running rdiff-backup I get no segfault, but shouldn't rdiff-backup be able to handle files that are being written to?
update2:
While backing up a different set of directories I get the segfault as well. Here is the last part of the strace output:
11:30:53.150681 read(8, "", 53248) = 0
11:30:53.150921 read(8, "", 65536) = 0
11:30:53.151140 close(8) = 0
11:30:53.151331 munmap(0xb6c2e000, 4096) = 0
11:30:53.154287 mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb670f000
11:30:53.157029 lstat64("/mnt/backup/backups/arch-server-system/usr/bin/php", {st_mode=S_IFREG|0755, st_size=9513272, ...}) = 0
11:30:53.157623 lstat64("/mnt/backup/backups/arch-server-system/rdiff-backup-data/increments/usr/bin/phpaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", 0xbfe2124c) = -1 ENOENT (No such file or directory)
11:30:53.158093 lstat64("/mnt/backup/backups/arch-server-system/rdiff-backup-data/increments/usr/bin", {st_mode=S_IFDIR|0700, st_size=147456, ...}) = 0
11:30:53.158664 lstat64("/mnt/backup/backups/arch-server-system/rdiff-backup-data/increments/usr/bin/php", 0xbfe2162c) = -1 ENOENT (No such file or directory)
11:30:53.159134 lstat64("/mnt/backup/backups/arch-server-system/usr/bin", {st_mode=S_IFDIR|0755, st_size=57344, ...}) = 0
11:30:53.159697 lstat64("/mnt/backup/backups/arch-server-system/usr/bin/rdiff-backup.tmp.65", 0xbfe2172c) = -1 ENOENT (No such file or directory)
11:30:53.160203 open("/mnt/backup/backups/arch-server-system/usr/bin/php", O_RDONLY|O_LARGEFILE) = 8
11:30:53.160478 fstat64(8, {st_mode=S_IFREG|0755, st_size=9513272, ...}) = 0
11:30:53.160938 open("/mnt/backup/backups/arch-server-system/usr/bin/rdiff-backup.tmp.65", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 10
11:30:53.161325 fstat64(10, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
11:30:53.161675 fstat64(9, {st_mode=S_IFREG|0755, st_size=9186120, ...}) = 0
11:30:53.161909 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6c2e000
11:30:53.162110 read(9, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\2\0\3\0\1\0\0\0\373h\6\0104\0\0\0"..., 65536) = 65536
11:30:53.171841 read(9, "ouble\0virtual_cwd_activate\0zend_"..., 65536) = 65536
11:30:53.176099 --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x904de44} ---
11:30:53.281097 +++ killed by SIGSEGV (core dumped) +++
./rdiff-backup_system.sh: line 50: 25075 Segmentation fault (core dumped) strace -Ff -tt /usr/bin/rdiff-backup --exclude-sockets --exclude /dev --exclude /home --exclude /media --exclude /mnt --exclude /proc --exclude /run --exclude /sys --exclude /tmp --exclude /var --exclude /srv / "$TARGET_LOCATION"update3: Opened a bugreport for rdiff-backup https://bugs.archlinux.org/task/47645
Last edited by rwd (2016-01-06 18:21:30)
Offline
#2 2016-01-08 10:48:43
- kyogen
- Member
- From: Germany
- Registered: 2010-11-08
- Posts: 24
- Website
Re: rdiff-backup segfault after upgrade to librsync-2.0.0-1
EDIT: Forgot about this: https://wiki.archlinux.org/index.php/Fo … pport_ONLY, sorry. The system which shows these problems is a Raspberry, so I should show myself out...
I'm using duplicity and have the same problem with coredumps after upgrading librsync to 2.0.0-1 some time ago (full system upgrade). Downgrading to 1.0.0-1 also solved the issue for me. So maybe a problem with librysnc?. When doing a full system backup to an external USB drive, I get this duplicity error:
Local and Remote metadata are synchronized, no sync needed.
Last inc backup left a partial set, restarting.
Last full backup date: Mon Jan 4 00:04:17 2016
RESTART: Volumes 2 to 2 failed to upload before termination.
Restarting backup at volume 2.
Restarting after volume 1, file root/.cache/duplicity/6b395f16f9e0dab917e14767c2adec7e/duplicity-full-signatures.20160103T230417Z.sigtar.gz, block 400
/root/backup.sh: line 22: 23005 Segmentation fault (core dumped) duplicity --verbosity notice --full-if-older-than 2M --num-retries 3 --asynchronous-upload --archive-dir /root/.cache/duplicity --log-file /var/log/duplicity.log --allow-source-mismatch --exclude /media --exclude /mnt --exclude /proc --exclude /sys --exclude /tmp --exclude /run --no-encryption "$src" "$dest"Relevant journactl output:
Jan 08 00:03:01 mybox systemd-coredump[23065]: Process 23005 (python2) of user 0 dumped core.
Stack trace of thread 23005:
#0 0x00000000763c7128 rs_search_for_block (librsync.so.2)After downgrading, the backup runs just fine:
Local and Remote metadata are synchronized, no sync needed.
Last inc backup left a partial set, restarting.
Last full backup date: Mon Jan 4 00:04:17 2016
RESTART: Volumes 2 to 2 failed to upload before termination.
Restarting backup at volume 2.
Restarting after volume 1, file root/.cache/duplicity/6b395f16f9e0dab917e14767c2adec7e/duplicity-full-signatures.20160103T230417Z.sigtar.gz, block 400
--------------[ Backup Statistics ]--------------
StartTime 1452247062.50 (Fri Jan 8 10:57:42 2016)
EndTime 1452247810.69 (Fri Jan 8 11:10:10 2016)
ElapsedTime 748.19 (12 minutes 28.19 seconds)
SourceFiles 101533
SourceFileSize 3231275874 (3.01 GB)
NewFiles 5243
NewFileSize 322094741 (307 MB)
DeletedFiles 3917
ChangedFiles 7463
ChangedFileSize 376958295 (359 MB)
ChangedDeltaSize 0 (0 bytes)
DeltaEntries 16623
RawDeltaSize 383665534 (366 MB)
TotalDestinationSizeChange 209599637 (200 MB)
Errors 0
-------------------------------------------------Trying a backup to the drive of a random test folder with librsync 2.0.0-1 also gives no errors.
Last edited by kyogen (2016-01-08 10:58:11)
Offline
#3 2016-01-08 16:24:23
- ewaller
- Administrator
- From: Pasadena, CA
- Registered: 2009-07-13
- Posts: 19,797
Re: rdiff-backup segfault after upgrade to librsync-2.0.0-1
EDIT: Forgot about this: https://wiki.archlinux.org/index.php/Fo … pport_ONLY, sorry. The system which shows these problems is a Raspberry, so I should show myself out...
Thank you for making me chuckle this morning 
Do you have only the Raspberry Pi, or do you also have a regular Arch Linux system that does not have the behavior?
Edit: Leaving this open because I do think it has bearing on Arch Linux
Last edited by ewaller (2016-01-08 16:25:15)
Nothing is too wonderful to be true, if it be consistent with the laws of nature -- Michael Faraday
Sometimes it is the people no one can imagine anything of who do the things no one can imagine. -- Alan Turing
---
How to Ask Questions the Smart Way
Offline
#4 2016-01-08 16:39:06
- kyogen
- Member
- From: Germany
- Registered: 2010-11-08
- Posts: 24
- Website
Re: rdiff-backup segfault after upgrade to librsync-2.0.0-1
Thank you for making me chuckle this morning smile
You're welcome 
Do you have only the Raspberry Pi, or do you also have a regular Arch Linux system that does not have the behavior?
I also have a desktop system running Arch, but I use duplicity only on the Raspberry for full system backup. I will try if I can reproduce on the desktop.
Offline
#5 2016-01-08 21:38:19
- klausenbusk
- Member
- Registered: 2012-08-04
- Posts: 16
Re: rdiff-backup segfault after upgrade to librsync-2.0.0-1
I can confirm this issue on ArchLinux 32 bit with duplicity.
jan 08 22:33:42 arch systemd-coredump[12752]: Process 12731 (python2) of user 1005 dumped core.
Stack trace of thread 12731:
#0 0x00000000b6c003fd rs_search_for_block (librsync.so.2)
#1 0x00000000b6bfccfc n/a (librsync.so.2)
#2 0x00000000b6bfdbd4 rs_job_iter (librsync.so.2)
#3 0x00000000b6c1ddfc n/a (_librsync.so)
#4 0x00000000b767bb55 PyCFunction_Call (libpython2.7.so.1.0)
#5 0x00000000b76de777 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#6 0x00000000b76ddd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#7 0x00000000b76e1625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#8 0x00000000b76ddc31 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#9 0x00000000b76ddd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#10 0x00000000b76ddd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#11 0x00000000b76ddd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#12 0x00000000b76e1625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#13 0x00000000b76ddc31 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#14 0x00000000b76e1625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#15 0x00000000b76ddc31 PyEval_EvalFrameEx (libpython2.7.so.1.0)
#16 0x00000000b76ddd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#17 0x00000000b76ddd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#18 0x00000000b76ddd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#19 0x00000000b76ddd1e PyEval_EvalFrameEx (libpython2.7.so.1.0)
#20 0x00000000b76e1625 PyEval_EvalCodeEx (libpython2.7.so.1.0)
#21 0x00000000b76e176b PyEval_EvalCode (libpython2.7.so.1.0)
#22 0x00000000b76fbad6 run_mod (libpython2.7.so.1.0)
#23 0x00000000b76fcf1b PyRun_FileExFlags (libpython2.7.so.1.0)
#24 0x00000000b76fe3a0 PyRun_SimpleFileExFlags (libpython2.7.so.1.0)
#25 0x00000000b76fe8e5 PyRun_AnyFileExFlags (libpython2.7.so.1.0)
#26 0x00000000b7711d82 Py_Main (libpython2.7.so.1.0)
#27 0x0000000008048594 main (python2.7)
#28 0x00000000b744d497 __libc_start_main (libc.so.6)
#29 0x00000000080485c2 _start (python2.7)Edit: Issue has already been reported upstream: https://github.com/librsync/librsync/issues/50
Last edited by klausenbusk (2016-01-08 21:49:12)
Offline