[Fixed:] Server crash on "Calculating file tree differences..."

Thomas_Huppertz · September 9, 2016, 8:48am

Hi,

i installed URServer Software on my Rasperian Pi 3
using the follwing package urbackup-server_2.0.33_armhf.deb

I installed the Clients on 3 different machines, inital File-Backups worked well, but now the Server keeps crashing and i have to restart it.

Here ist the log-File Output:

`
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/urbackup.js
2016-09-08 13:25:19: Sending file “/usr/share/urbackup/www/js/md5.js”
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/md5.js
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/md5.js done
2016-09-08 13:25:19: Sending file “/usr/share/urbackup/www/js/sjcl.js”
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/sjcl.js
2016-09-08 13:25:19: Sending file “/usr/share/urbackup/www/js/translation.js”
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/translation.js
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/sjcl.js done
2016-09-08 13:25:19: Sending file “/usr/share/urbackup/www/js/nprogress.js”
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/nprogress.js
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/nprogress.js done
2016-09-08 13:25:19: Sending file “/usr/share/urbackup/www/js/jquery.base64.min.js”
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/jquery.base64.min.js
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/jquery.base64.min.js done
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/templates.js done
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/urbackup.js done
2016-09-08 13:25:19: Sending file “/usr/share/urbackup/www/css/urbackup_extra.css”
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/css/urbackup_extra.css
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/css/urbackup_extra.css done
2016-09-08 13:25:19: Sending file “/usr/share/urbackup/www/images/urbackup.png”
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/images/urbackup.png
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/images/urbackup.png done
2016-09-08 13:25:19: Sending file: /usr/share/urbackup/www/js/translation.js done
2016-09-08 13:28:01: New Backupclient: thomashsmacbook.fritz.box
2016-09-08 13:28:11: Connection broken: Sending Identity to client “thomashsmacbook.fritz.box” failed. Retrying soon…
2016-09-08 13:29:24: WARNING: Restarting shadow copy of C:\ because it was started by this server
2016-09-08 13:29:24: Scanning for changed hard links on volume of “Daten”…
2016-09-08 13:29:24: Indexing of “Daten” done. 1 filesystem lookups 147 db lookups and 0 db updates
2016-09-08 13:29:24: DESKTOP-B2MA34Q: Doing backup with hashed transfer…
2016-09-08 13:29:24: DESKTOP-B2MA34Q: Connecting to client…
2016-09-08 13:29:24: DESKTOP-B2MA34Q: Loading file list…
2016-09-08 13:29:24: Flushing FileClient…
2016-09-08 13:30:14: Socket has error: 113
2016-09-08 13:30:14: Connecting to ClientService of “thomashsmacbook.fritz.box” failed: Sending Identity to client “thomashsmacbook.fritz.box” failed. Retrying soon…
2016-09-08 13:30:24: Loading “urbackup/filelist.ub”. 73% finished 386.828 KB/525.695 KB at 52.296 KBit/s
2016-09-08 13:30:45: DESKTOP-B2MA34Q Starting incremental backup…
2016-09-08 13:30:45: DESKTOP-B2MA34Q: Calculating file tree differences…

***************** CRASH HERE ****************

2016-09-09 10:36:56: Starting HTTP-Server on port 55414
2016-09-09 10:36:56: HTTP: Server started up successfully!
2016-09-09 10:36:56: SQLite: recovered 16 frames from WAL file /var/urbackup/backup_server.db-wal code: 283
2016-09-09 10:36:56: SQLite: recovered 1 frames from WAL file /var/urbackup/backup_server_link_journal.db-wal code: 283
2016-09-09 10:36:56: SQLite: recovered 4 frames from WAL file /var/urbackup/backup_server_settings.db-wal code: 283
2016-09-09 10:37:02: Started UrBackup…
2016-09-09 10:37:02: Removing temporary files…
2016-09-09 10:37:02: Recreating temporary folder…
2016-09-09 10:37:02: Testing if backup destination can handle subvolumes and snapshots…
2016-09-09 10:37:02: Backup destination cannot handle subvolumes and snapshots. Snapshots disabled.
2016-09-09 10:37:02: Testing if backup destination can handle filesystem transactions…
2016-09-09 10:37:02: Binding to interface eth0 for broadcasting…
2016-09-09 10:37:02: Broadcasting on interface IP 192.168.178.41
2016-09-09 10:37:02: UrBackup Server start up complete.
2016-09-09 10:37:02: Looking for old Sessions… 0 sessions
2016-09-09 10:37:02: Server started up successfully!
2016-09-09 10:38:02: Downloading version file…
2016-09-09 10:38:02: Downloading version file…
2016-09-09 10:38:02: Downloading version file…
2016-09-09 10:38:02: Downloading server version info…
`
the dmsg-command shows:

[119493.699282] brcmfmac: brcmf_sdio_readframes: RXHEADER FAILED: -110 [119493.699306] brcmfmac: brcmf_sdio_rxfail: abort command, terminate frame, send NAK

Thomas_Huppertz · September 9, 2016, 7:00pm

I have tried to run via console …

that is the output:

pi@raspi:~ $ sudo urbackupsrv run 2016-09-09 20:54:11: Starting HTTP-Server on port 55414 2016-09-09 20:54:11: HTTP: Server started up successfully! 2016-09-09 20:54:12: SQLite: recovered 5 frames from WAL file /var/urbackup/backup_server.db-wal code: 283 2016-09-09 20:54:12: SQLite: recovered 1 frames from WAL file /var/urbackup/backup_server_link_journal.db-wal code: 283 2016-09-09 20:54:12: Started UrBackup... 2016-09-09 20:54:12: Removing temporary files... 2016-09-09 20:54:12: Recreating temporary folder... TEST FAILED: Creating test subvolume failed 2016-09-09 20:54:12: Backup destination cannot handle subvolumes and snapshots. Snapshots disabled. 2016-09-09 20:54:12: Broadcasting on interface IP 192.168.178.41 2016-09-09 20:54:13: UrBackup Server start up complete. 2016-09-09 20:54:13: Looking for old Sessions... 0 sessions 2016-09-09 20:54:13: Server started up successfully! 2016-09-09 20:54:44: New Backupclient: LAPTOP-F5SABT3B 2016-09-09 20:54:44: New Backupclient: thomashsmacbook.fritz.box 2016-09-09 20:54:44: Starting incremental file backup... 2016-09-09 20:54:46: Starting incremental file backup... 2016-09-09 20:55:04: Backing up "Documents" without snapshot. 2016-09-09 20:55:04: Indexing of "Documents" done. 95 filesystem lookups 0 db lookups and 0 db updates 2016-09-09 20:55:04: Backing up "Downloads" without snapshot. 2016-09-09 20:55:04: Following symbolic link at "/Users/thomas/Downloads/SupaView.app/Contents/Frameworks/Sparkle.framework/Versions/A/Resources/fr_CA.lproj" to "/Users/andym/Development/Build Products/Release/Sparkle.framework/Resources/fr.lproj" confirms symlink backup target ".symlink_fr.lproj" to "/Users/andym/Development/Build Products/Release/Sparkle.framework/Resources/fr.lproj" 2016-09-09 20:55:04: Indexing of "Downloads" done. 238 filesystem lookups 0 db lookups and 0 db updates 2016-09-09 20:55:04: Backing up "Desktop" without snapshot. 2016-09-09 20:55:04: Indexing of "Desktop" done. 7 filesystem lookups 0 db lookups and 0 db updates 2016-09-09 20:55:04: Backing up ".symlink_fr.lproj" without snapshot. 2016-09-09 20:55:04: thomashsmacbook.fritz.box: Loading file list... 2016-09-09 20:55:05: thomashsmacbook.fritz.box: Calculating file tree differences...

It keeps crashing on calculating the tree differences

uroni · September 9, 2016, 8:11pm

If you run it with sudo gdb --args urbackupsrv run -v debug and then enter bt once it crashed it will show the exact location it crashes. Thanks!

uroni · September 9, 2016, 8:41pm

Also helpful to reproduce the problem would be the C:\Program Files\UrBackup\urbackup\data\filelist.ub file from the client and the matching clientlist_b_BACKUPID.ub file of the client from /var/urbackup.

Thomas_Huppertz · September 9, 2016, 9:41pm

2016-09-09 23:39:16: Flushing FileClient…
2016-09-09 23:39:16: DESKTOP-B2MA34Q Starting incremental backup…
2016-09-09 23:39:16: DESKTOP-B2MA34Q: Calculating file tree differences…
[Inferior 1 (process 21363) exited with code 0204]
(gdb)
(gdb) bt
No stack.

Seems there is no Stack

Or Do i so something wrong?

Have no Debüg Symbols Loaded

uroni · September 9, 2016, 10:54pm

That’s SIGILL (illegal instruction). So this hints at me compiling it wrong. On the other hand you are not the first one to use it on a RPi.

Idk why gdb does not catch the signal. Perhaps handle SIGILL stop helps, thougth that should be the default…

uroni · September 9, 2016, 11:01pm

Ok it’s a bug in gdb: https://github.com/raspberrypi/linux/issues/766

Thomas_Huppertz · September 10, 2016, 7:37am

filelist.zip (195.5 KB)

Is the Client filelist (zipped)

Thomas_Huppertz · September 10, 2016, 7:44am

clientlist_b_2.zip (195.5 KB)

Client List

Is this enough Information? Or do you Need that stack trace ?

And what should i do to make it work …?

Execute: handle SIGILL stop
before i start to run the Server?

Thomas_Huppertz · September 10, 2016, 9:46am

Executet the command before run, but no better result… see yourself

pi@raspi:~ $ sudo gdb --args sudo urbackupsrv run -v debug GNU gdb (Raspbian 7.7.1+dfsg-5) 7.7.1 Copyright (C) 2014 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "arm-linux-gnueabihf". Type "show configuration" for configuration details. For bug reporting instructions, please see: <http://www.gnu.org/software/gdb/bugs/>. Find the GDB manual and other documentation resources online at: <http://www.gnu.org/software/gdb/documentation/>. For help, type "help". Type "apropos word" to search for commands related to "word"... Reading symbols from sudo...(no debugging symbols found)...done. (gdb) handle SIGILL stop Signal Stop Print Pass to program Description SIGILL Yes Yes Yes Illegal instruction (gdb) r Starting program: /usr/bin/sudo urbackupsrv run -v debug [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1". 2016-09-10 11:43:16: Starting HTTP-Server on port 55414 2016-09-10 11:43:16: HTTP: Server started up successfully! 2016-09-10 11:43:16: SQLite: recovered 7 frames from WAL file /var/urbackup/backup_server.db-wal code: 283 2016-09-10 11:43:17: SQLite: recovered 1 frames from WAL file /var/urbackup/backup_server_link_journal.db-wal code: 283 2016-09-10 11:43:17: Started UrBackup... 2016-09-10 11:43:17: Removing temporary files... 2016-09-10 11:43:17: Recreating temporary folder... 2016-09-10 11:43:17: Testing if backup destination can handle subvolumes and snapshots... TEST FAILED: Creating test subvolume failed 2016-09-10 11:43:17: Backup destination cannot handle subvolumes and snapshots. Snapshots disabled. 2016-09-10 11:43:17: Testing if backup destination can handle filesystem transactions... 2016-09-10 11:43:17: Binding to interface eth0 for broadcasting... 2016-09-10 11:43:17: Broadcasting on interface IP 192.168.178.41 2016-09-10 11:43:17: UrBackup Server start up complete. 2016-09-10 11:43:17: Looking for old Sessions... 0 sessions 2016-09-10 11:43:17: Server started up successfully! 2016-09-10 11:43:48: New Backupclient: DESKTOP-B2MA34Q 2016-09-10 11:43:48: Getting client settings... 2016-09-10 11:43:48: Flushing FileClient... 2016-09-10 11:43:48: Sending backup incr interval... 2016-09-10 11:43:48: Starting incremental file backup... 2016-09-10 11:43:48: DESKTOP-B2MA34Q: Connecting for filelist... 2016-09-10 11:43:48: DESKTOP-B2MA34Q: Waiting for filelist 2016-09-10 11:44:17: Downloading version file... 2016-09-10 11:44:17: Downloading version file... 2016-09-10 11:44:17: Downloading version file... 2016-09-10 11:44:17: Downloading server version info... 2016-09-10 11:44:36: WARNING: Restarting shadow copy of C:\ because it was started by this server 2016-09-10 11:44:36: Scanning for changed hard links on volume of "Daten"... 2016-09-10 11:44:36: Indexing of "Daten" done. 1 filesystem lookups 147 db lookups and 0 db updates 2016-09-10 11:44:36: DESKTOP-B2MA34Q: Doing backup with hashed transfer... 2016-09-10 11:44:36: DESKTOP-B2MA34Q: Connecting to client... 2016-09-10 11:44:36: DESKTOP-B2MA34Q: Loading file list... 2016-09-10 11:44:36: Flushing FileClient... 2016-09-10 11:44:36: DESKTOP-B2MA34Q Starting incremental backup... 2016-09-10 11:44:36: DESKTOP-B2MA34Q: Calculating file tree differences... [Inferior 1 (process 23908) exited with code 0204] (gdb) bt No stack. (gdb)

uroni · September 10, 2016, 10:02am

Thanks for the lists. Will test with those.

As described in https://github.com/raspberrypi/linux/issues/766 you will either need a kernel build with CONFIG_OABI_COMPAT=y or gdb >= 7.10. As always the problem is known and fixed since half a year, but the fix did not make it into Debian (if this is indeed the issue)…

uroni · September 10, 2016, 1:39pm

Unfortunately I cannot reproduce the problem with the two files.

Thomas_Huppertz · September 10, 2016, 2:40pm

Could i do anything to help you?
Do you want to connect to my raspi?

uroni · September 10, 2016, 2:58pm

Ok, pm or mail… thanks!

Thomas_Huppertz · September 10, 2016, 10:15pm

What is your Mail-Adress?
So you Need a Client Running to Test it? then i will keep it Running for your Test

uroni · September 12, 2016, 2:38pm

Could be because I compiled it for Debian armhf and you are using Raspbian.

Seems to work now when I compile it with -mfpu=vfp.

Thomas_Huppertz · September 22, 2016, 12:38pm

The solution worked. Two weeks later - no more crashes

Mihail_Cheshuin · January 16, 2018, 4:14pm

Hello, I have the same problem on the entware-ng, urbackup-server-2.1.20:

2018-01-16 09:17:13: Starting HTTP-Server on port 55414
2018-01-16 09:17:13: HTTP: Server started up successfully!
2018-01-16 09:17:13: SQLite: recovered 268 frames from WAL file /opt/var/urbackup/backup_server.db-wal code: 283
2018-01-16 09:17:13: SQLite: recovered 2359 frames from WAL file /opt/var/urbackup/backup_server_files.db-wal code: 283
2018-01-16 09:17:13: SQLite: recovered 14 frames from WAL file /opt/var/urbackup/backup_server_link_journal.db-wal code: 283
2018-01-16 09:17:13: SQLite: recovered 476 frames from WAL file /opt/var/urbackup/backup_server_settings.db-wal code: 283
2018-01-16 09:17:13: SQLite: recovered 268 frames from WAL file /opt/var/urbackup/backup_server.db-wal code: 283
2018-01-16 09:17:13: SQLite: recovered 476 frames from WAL file /opt/var/urbackup/backup_server_settings.db-wal code: 283
2018-01-16 09:17:13: SQLite: recovered 2359 frames from WAL file /opt/var/urbackup/backup_server_files.db-wal code: 283
2018-01-16 09:17:13: SQLite: recovered 14 frames from WAL file /opt/var/urbackup/backup_server_link_journal.db-wal code: 283
2018-01-16 09:17:13: Started UrBackup…
2018-01-16 09:17:13: Removing temporary files…
2018-01-16 09:17:13: Recreating temporary folder…
Testing for btrfs…
TEST FAILED: Creating test btrfs subvolume failed
Testing for zfs…
TEST FAILED: Creating test zfs volume “tank/images/testA54hj5luZtlorr494” failed
2018-01-16 09:17:14: Backup destination cannot handle subvolumes and snapshots. Snapshots disabled.
TEST FAILED: Please compile with mountvhd (./configure --with-mountvhd)
2018-01-16 09:17:14: Image mounting disabled: TEST FAILED: Please compile with mountvhd (./configure --with-mountvhd)
2018-01-16 09:17:14: WARNING: File backup [id=2, path=180116-0912, backuptime=2018-01-16 09:15:39, clientid=1, client=user-PC] is incomplete. Deleting it.
2018-01-16 09:17:14: WARNING: Deleting file backup [id=2, path=180116-0912, backuptime=2018-01-16 09:15:39, clientid=1, client=user-PC]…
2018-01-16 09:17:14: Start-up recovery finished.
2018-01-16 09:17:14: Broadcasting on interface IP 192.168.1.3
2018-01-16 09:17:14: UrBackup Server start up complete.
2018-01-16 09:17:14: Server started up successfully!
2018-01-16 09:17:14: Looking for old Sessions… 0 sessions
2018-01-16 09:17:15: Downloading version file…
2018-01-16 09:17:15: Downloading version file…
2018-01-16 09:17:15: Downloading version file…
2018-01-16 09:17:15: Downloading server version info…
2018-01-16 09:17:15: Downloading dataplan database…
2018-01-16 09:17:46: New Backupclient: user-PC
2018-01-16 09:17:46: Sending Identity to client “user-PC” failed. Retrying soon…
2018-01-16 09:17:47: Starting scheduled incremental file backup…
2018-01-16 09:20:31: Selected no components to backup
2018-01-16 09:20:31: WARNING: Restarting shadow copy of D:\ because it was started by this server
2018-01-16 09:20:31: Scanning for changed hard links on volume of “D:”…
2018-01-16 09:20:31: Indexing of “Кузя” done. 1 filesystem lookups 26 db lookups and 0 db updates
2018-01-16 09:20:31: user-PC: Loading file list…
2018-01-16 09:20:36: user-PC: Calculating file tree differences…
Bus error

help me please.

uroni · January 17, 2018, 3:36pm

No idea how it is compiled and you should also post /proc/cpuinfo, I guess. SIGBUS could be caused by an unaligned memory access.

Mihail_Cheshuin · January 18, 2018, 7:34am

Package from this repository:

/opt/root # cat /proc/cpuinfo
Processor : ARMv7 Processor rev 2 (v7l)
BogoMIPS : 1001.88
Features : swp half thumb fastmult vfp edsp neon vfpv3
CPU implementer : 0x41
CPU architecture: 7
CPU variant : 0x3
CPU part : 0xc08
CPU revision : 2

Hardware : sun5i
Revision : a13a
Serial : 0bc2a5d131303030504b413316254154