Crash on server startup FreeNAS, fresh install

Server
1

I have been running urbackup in a FreeNAS 9.10 jail for years, and it worked great. I love teh program. I took the plunge recently to update the FreeNAS to 11.3, and since then urbackupsrv is crashing on startup.

I tried creating a new jail and setting up a fresh copy of urbackup. On the first run, it worked. I was able to get in to the web interface and point the backup data directory to the mounted zfs datastore and create an admin user. After restarting it however, it also crashes on start.

I compiled urbackup server from the latest source, 2.4.13.

uname -a
FreeBSD urbackup-test 11.3-RELEASE-p14 FreeBSD 11.3-RELEASE-p14 #0 r325575+c936002dbe2(HEAD): Mon Sep 28 10:46:56 EDT 2020 root@tnbuilds05.tn.ixsystems.net:/freenas-releng/freenas/_BE/objs/freenas-releng/freenas/_BE/os/sys/FreeNAS.amd64 amd64

The logs look like this:
2020-10-30 10:12:39: Starting HTTP-Server on port 55414
2020-10-30 10:12:39: HTTP: Server started up successfully!
2020-10-30 10:12:39: SQLite: recovered 4 frames from WAL file /usr/local/var/urbackup/backup_server.db-wal code: 283
2020-10-30 10:12:39: SQLite: recovered 1 frames from WAL file /usr/local/var/urbackup/backup_server_link_journal.db-wal code: 283
2020-10-30 10:12:39: SQLite: recovered 10 frames from WAL file /usr/local/var/urbackup/backup_server_settings.db-wal code: 283
2020-10-30 10:12:39: SQLite: recovered 4 frames from WAL file /usr/local/var/urbackup/backup_server.db-wal code: 283
2020-10-30 10:12:39: SQLite: recovered 10 frames from WAL file /usr/local/var/urbackup/backup_server_settings.db-wal code: 283
2020-10-30 10:12:39: SQLite: recovered 1 frames from WAL file /usr/local/var/urbackup/backup_server_link_journal.db-wal code: 283

Running it through tmux and gdb, I get the following three crashes:

(gdb) run
Starting program: /usr/local/bin/urbackupsrv run -g 104857600 -u root -v debug
2020-10-30 10:09:44: Starting HTTP-Server on port 55414
2020-10-30 10:09:44: HTTP: Server started up successfully!
2020-10-30 10:09:44: SQLite: recovered 4 frames from WAL file /usr/local/var/urbackup/backup_server.db-wal code: 283
2020-10-30 10:09:44: SQLite: recovered 1 frames from WAL file /usr/local/var/urbackup/backup_server_link_journal.db-wal code: 283
2020-10-30 10:09:44: SQLite: recovered 10 frames from WAL file /usr/local/var/urbackup/backup_server_settings.db-wal code: 283

Program received signal SIGFPE, Arithmetic exception.
0x0000000000511eec in sqlite3StartTable (pParse=, pName1=, pName2=, isTemp=89079625,
isView=, isVirtual=, noErr=0) at sqlite/sqlite3.c:31595
31595 h = strHash(pKey) % pH->htsize;
Current language: auto; currently minimal
(gdb) bt
#0 0x0000000000511eec in sqlite3StartTable (pParse=, pName1=, pName2=, isTemp=89079625,
isView=, isVirtual=, noErr=0) at sqlite/sqlite3.c:31595
Segmentation fault

(gdb) run
Starting program: /usr/local/bin/urbackupsrv run -g 104857600 -u root -v debug
2020-10-30 10:11:13: Starting HTTP-Server on port 55414
2020-10-30 10:11:13: HTTP: Server started up successfully!
2020-10-30 10:11:13: SQLite: recovered 4 frames from WAL file /usr/local/var/urbackup/backup_server.db-wal code: 283
2020-10-30 10:11:13: SQLite: recovered 1 frames from WAL file /usr/local/var/urbackup/backup_server_link_journal.db-wal code: 283
2020-10-30 10:11:13: SQLite: recovered 10 frames from WAL file /usr/local/var/urbackup/backup_server_settings.db-wal code: 283
2020-10-30 10:11:13: SQLite: recovered 4 frames from WAL file /usr/local/var/urbackup/backup_server.db-wal code: 283
2020-10-30 10:11:13: SQLite: recovered 10 frames from WAL file /usr/local/var/urbackup/backup_server_settings.db-wal code: 283
2020-10-30 10:11:13: SQLite: recovered 1 frames from WAL file /usr/local/var/urbackup/backup_server_link_journal.db-wal code: 283

Program received signal SIGSEGV, Segmentation fault.
0x00000000004ba498 in sqlite3FindTable (db=0x805441208, zName=0x805508b68 “misc”, zDatabase=0x0)
Current language: auto; currently minimal
(gdb) bt
#0 0x00000000004ba498 in sqlite3FindTable (db=0x805441208, zName=0x805508b68 “misc”, zDatabase=0x0)
Segmentation fault

(gdb) run
Starting program: /usr/local/bin/urbackupsrv run -g 104857600 -u root -v debug
2020-10-30 10:12:45: Starting HTTP-Server on port 55414
2020-10-30 10:12:45: HTTP: Server started up successfully!
2020-10-30 10:12:45: SQLite: recovered 4 frames from WAL file /usr/local/var/urbackup/backup_server.db-wal code: 283
2020-10-30 10:12:45: SQLite: recovered 1 frames from WAL file /usr/local/var/urbackup/backup_server_link_journal.db-wal code: 283
2020-10-30 10:12:45: SQLite: recovered 10 frames from WAL file /usr/local/var/urbackup/backup_server_settings.db-wal code: 283

Program received signal SIGBUS, Bus error.
sqlite3MemSize (pPrior=0x5b8000000080541) at sqlite/sqlite3.c:22629
22629 return (int)p[0];
(gdb) bt
#0 sqlite3MemSize (pPrior=0x5b8000000080541) at sqlite/sqlite3.c:22629
Segmentation fault

2

Since it seems to occur during startup, maybe run it in valgrind? pkg install valgrind then valgrind /usr/local/bin/urbackupsrv run -g 104857600 -u root -v debug.

3

It took a while to compile valgrind, since I had to install it from ports. When I run urbackupsrv through it, it does not crash. The output around that part is included below. If you would like the rest of the output, let me know.

2020-10-30 12:01:52: SQLite: recovered 4 frames from WAL file /usr/local/var/urbackup/backup_server.db-wal code: 283
2020-10-30 12:01:52: SQLite: recovered 1 frames from WAL file /usr/local/var/urbackup/backup_server_link_journal.db-wal code: 283
2020-10-30 12:01:52: SQLite: recovered 10 frames from WAL file /usr/local/var/urbackup/backup_server_settings.db-wal code: 283
2020-10-30 12:01:52: SQLite: recovered 4 frames from WAL file /usr/local/var/urbackup/backup_server.db-wal code: 283
2020-10-30 12:01:52: SQLite: recovered 10 frames from WAL file /usr/local/var/urbackup/backup_server_settings.db-wal code: 283
2020-10-30 12:01:53: SQLite: recovered 1 frames from WAL file /usr/local/var/urbackup/backup_server_link_journal.db-wal code: 283
==52728== Syscall param write(buf) points to uninitialised byte(s)
==52728== at 0x691D8BA: _write (in /lib/libc.so.7)
==52728== by 0x682F8C1: sem_open (in /lib/libc.so.7)
==52728== by 0x92FBC8: mdb_env_setup_locks (in /usr/local/bin/urbackupsrv)
==52728== by 0x92F29C: mdb_env_open (in /usr/local/bin/urbackupsrv)
==52728== by 0x762727: LMDBFileIndex::create_env() (LMDBFileIndex.cpp:537)
==52728== by 0x76222B: LMDBFileIndex::LMDBFileIndex(bool) (LMDBFileIndex.cpp:68)
==52728== by 0x7620DB: LMDBFileIndex::initFileIndex() (LMDBFileIndex.cpp:49)
==52728== by 0x76B2FA: create_files_index(SStartupStatus&) (create_files_index.cpp:289)
==52728== by 0x608848: LoadActions_urbackupserver (dllmain.cpp:723)
==52728== by 0x450BD5: CServer::LoadStaticPlugins() (Server.cpp:2246)
==52728== by 0x4656E5: main_fkt(int, char**) (main.cpp:554)
==52728== by 0x462FEF: main_fkt_catch(int, char**) (main.cpp:130)
==52728== Address 0x7fbffd344 is on thread 1’s stack
==52728== in frame #1, created by sem_open (???: )
==52728==
==52728== Syscall param write(buf) points to uninitialised byte(s)
==52728== at 0x691D8BA: _write (in /lib/libc.so.7)
==52728== by 0x682F8C1: sem_open (in /lib/libc.so.7)
==52728== by 0x92FBF8: mdb_env_setup_locks (in /usr/local/bin/urbackupsrv)
==52728== by 0x92F29C: mdb_env_open (in /usr/local/bin/urbackupsrv)
==52728== by 0x762727: LMDBFileIndex::create_env() (LMDBFileIndex.cpp:537)
==52728== by 0x76222B: LMDBFileIndex::LMDBFileIndex(bool) (LMDBFileIndex.cpp:68)
==52728== by 0x7620DB: LMDBFileIndex::initFileIndex() (LMDBFileIndex.cpp:49)
==52728== by 0x76B2FA: create_files_index(SStartupStatus&) (create_files_index.cpp:289)
==52728== by 0x608848: LoadActions_urbackupserver (dllmain.cpp:723)
==52728== by 0x450BD5: CServer::LoadStaticPlugins() (Server.cpp:2246)
==52728== by 0x4656E5: main_fkt(int, char**) (main.cpp:554)
==52728== by 0x462FEF: main_fkt_catch(int, char**) (main.cpp:130)
==52728== Address 0x7fbffd344 is on thread 1’s stack
==52728== in frame #1, created by sem_open (???: )
==52728==
2020-10-30 12:01:53: Started UrBackup…
2020-10-30 12:01:53: Removing temporary files…
2020-10-30 12:01:53: Recreating temporary folder…

4

After researching these messages, it seems like they may be benign (I’m not an expert by any means). I’ve attached the full valgrind log, though I don’t know if anything there will help.
2020-10-30-valgrind.log (130.0 KB)

5

I resolved this issue by using the urbackup-server that was provided by pkg instead of compiling from source. I previously had compiled from source, in part due to lack of support in the older FreeNAS version. After installing it from the package manager in a new jail, I was able to migrate my data and everything is working now.

6

A little bit of a thread resurrection but not too much I hope.
I cannot build any version of Urbackup-Server in a jail on TrueNAS. I have tried with TrueNAS versions 11.2 to 12.0.
PKG installs of 2.4.12 are fine but I wanted to move on from there.
After a build Urbackup server starts one-time but fails to start again unless repair-database is run first. Errors as in the post above.
I tried to use Valgrind but I was unsuccessful.
Even doing a package install followed by a build of the same version shows the same failure.
I have built Urbackup many times before but maybe one of the pre-requisite packages has changed.

7

Valgrind output of the failurevalgrind output.txt (17.9 KB)

8

Perhaps try to configure with the same flags as freebsd ports uses --without-embedded-sqlite3 --without-embedded-lmdb --without-embedded-lua…

9

2.4.12 installs fine from ports.
Those configure options don’t work for me, it just complains about missing packages and if I install them with pkg before the build I get the same result

10

Exactly the same version packages are present if I install 2.4.12 with pkg; which runs and if I build 2.4.12 which fails ???