URBackup server process dies when client attempts to connect

Server
1

UrBackup server process dies

Urbackup server process dies whenever a client tries to connect.

I have stopped all clients, then started the server process, left over night and process never dies. Once I start 1 client (it does not matter which) the server process dies after the client tries to connect. This system was working before, had to reboot server to re-establish connection to NAS system after network switch crashed. Reboot was done via shutdown command.

The /var/urbackup directory and its sub-directories are owned by urbackup.

I have done a ‘start_urbackup_server --repair_database’ but that has not helped.

Any ideas?

Thanks,

Wes Hegge

Environment info and logs below.

Installed via yum from the kot1grun repos.
Urback Server 1.4.14
Server OS: CentOS 6.7

Urback Client 1.4.11
Client OS: CentOS 6.4

Server Log

2016-05-23 11:07:17: Binding to interface eth1 for broadcasting…
2016-05-23 11:07:18: UrBackup Server start up complete.
2016-05-23 11:07:18: Created new database connection for urbackup/backup_server.db
2016-05-23 11:07:18: Starting HTTP-Server on port 55414
2016-05-23 11:07:18: HTTP: Server started up sucessfully!
2016-05-23 11:07:18: Creating SOCKET…
2016-05-23 11:07:18: Looking for old Sessions… 0 sessions
2016-05-23 11:07:18: done.
2016-05-23 11:07:18: Server started up sucessfully!
2016-05-23 11:07:18: Created new database connection for urbackup/backup_server.db
2016-05-23 11:08:18: ERROR: Urlplugin not found. Cannot download client for autoupdate.
2016-05-23 11:08:18: ERROR: Urlplugin not found. Cannot download server version info.
2016-05-23 11:09:42: HTTP: No available slots… starting new Worker
2016-05-23 11:09:42: Sending file “/var/urbackup/www”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/index.htm
2016-05-23 11:09:42: Sending file: /var/urbackup/www/index.htm done
2016-05-23 11:09:42: HTTP: No available slots… starting new Worker
2016-05-23 11:09:42: HTTP: No available slots… starting new Worker
2016-05-23 11:09:42: Sending file “/var/urbackup/www/jquery.jqplot.min.css”
2016-05-23 11:09:42: HTTP: No available slots… starting new Worker
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jquery.jqplot.min.css
2016-05-23 11:09:42: HTTP: No available slots… starting new Worker
2016-05-23 11:09:42: HTTP: No available slots… starting new Worker
2016-05-23 11:09:42: Sending file “/var/urbackup/www/datatable.css”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/datatable.css
2016-05-23 11:09:42: Sending file “/var/urbackup/www/layout.css”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/layout.css
2016-05-23 11:09:42: Sending file “/var/urbackup/www/dataTables.tableTools.min.css”
2016-05-23 11:09:42: Sending file “/var/urbackup/www/dataTables.colVis.min.css”
2016-05-23 11:09:42: Sending file “/var/urbackup/www/jquery.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/dataTables.tableTools.min.css
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jquery.js
2016-05-23 11:09:42: Sending file: /var/urbackup/www/dataTables.colVis.min.css
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jquery.jqplot.min.css done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/layout.css done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/datatable.css done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/dataTables.tableTools.min.css done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/dataTables.colVis.min.css done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/dataTables.tableTools.min.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/dataTables.tableTools.min.js
2016-05-23 11:09:42: Sending file: /var/urbackup/www/dataTables.tableTools.min.js done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/jquery.jqplot.min.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jquery.jqplot.min.js
2016-05-23 11:09:42: Sending file “/var/urbackup/www/jqplot.pieRenderer.min.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jqplot.pieRenderer.min.js
2016-05-23 11:09:42: Sending file “/var/urbackup/www/jqplot.barRenderer.min.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jqplot.barRenderer.min.js
2016-05-23 11:09:42: Sending file “/var/urbackup/www/dust-full.min.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/dust-full.min.js
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jqplot.pieRenderer.min.js done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jquery.js done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jqplot.barRenderer.min.js done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/jqplot.highlighter.min.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jqplot.highlighter.min.js
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jqplot.highlighter.min.js done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/templates.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/templates.js
2016-05-23 11:09:42: Sending file “/var/urbackup/www/urbackup.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/urbackup.js
2016-05-23 11:09:42: Sending file “/var/urbackup/www/default_user_rights.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/default_user_rights.js
2016-05-23 11:09:42: Sending file: /var/urbackup/www/templates.js done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/md5.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/md5.js
2016-05-23 11:09:42: Sending file: /var/urbackup/www/md5.js done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/default_user_rights.js done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/urbackup.js done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/dataTables.colVis.min.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/dataTables.colVis.min.js
2016-05-23 11:09:42: Sending file “/var/urbackup/www/jqplot.dateAxisRenderer.min.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jqplot.dateAxisRenderer.min.js
2016-05-23 11:09:42: Sending file “/var/urbackup/www/urbackup_functions.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/urbackup_functions.js
2016-05-23 11:09:42: Sending file: /var/urbackup/www/dataTables.colVis.min.js done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/tabber-minimized.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/urbackup_functions.js done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/tabber-minimized.js
2016-05-23 11:09:42: Sending file: /var/urbackup/www/tabber-minimized.js done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/jquery.dataTables.min.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jquery.dataTables.min.js
2016-05-23 11:09:42: Sending file “/var/urbackup/www/translation.js”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/translation.js
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jquery.dataTables.min.js done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/translation.js done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jqplot.dateAxisRenderer.min.js done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/jquery.jqplot.min.js done
2016-05-23 11:09:42: Sending file: /var/urbackup/www/dust-full.min.js done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/indicator.gif”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/indicator.gif
2016-05-23 11:09:42: Sending file: /var/urbackup/www/indicator.gif done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/header.png”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/header.png
2016-05-23 11:09:42: Sending file “/var/urbackup/www/favicon.ico”
2016-05-23 11:09:42: Sending file: /var/urbackup/www/header.png done
2016-05-23 11:09:42: Sending file “/var/urbackup/www/favicon.ico”
2016-05-23 11:09:42: Created new database connection for urbackup/backup_server.db
2016-05-23 11:09:43: Created new database connection for urbackup/backup_server.db
2016-05-23 11:09:44: Sending file “/var/urbackup/www/sort_both.png”
2016-05-23 11:09:44: Sending file: /var/urbackup/www/sort_both.png
2016-05-23 11:09:44: Sending file “/var/urbackup/www/sort_asc.png”
2016-05-23 11:09:44: Sending file: /var/urbackup/www/sort_asc.png
2016-05-23 11:09:44: Sending file: /var/urbackup/www/sort_both.png done
2016-05-23 11:09:44: Sending file: /var/urbackup/www/sort_asc.png done
2016-05-23 11:09:58: Sending file “/var/urbackup/www/sort_desc.png”
2016-05-23 11:09:58: Sending file: /var/urbackup/www/sort_desc.png
2016-05-23 11:09:58: Sending file: /var/urbackup/www/sort_desc.png done

2016-05-23 11:11:59: New Backupclient: ILOakbVmAPIServer
2016-05-23 11:11:59: Sending Identity to client “ILOakbVmAPIServer” failed. Retrying soon…

Client Log

2016-05-23 16:11:23: Started UrBackupClient Backend…
2016-05-23 16:11:23: FileSrv: Binding udp socket at port 35622…
2016-05-23 16:11:23: FileSrv: done.
2016-05-23 16:11:23: FileSrv: Servername: -ILOakbVmAPIServer-
2016-05-23 16:11:23: FileSrv: Server started up sucessfully
2016-05-23 16:11:23: FileSrv: UDP Thread startet
2016-05-23 16:11:24: Internet only mode not enabled. Waiting for local server for 3:00…
2016-05-23 16:11:24: Looking for old Sessions… 0 sessions
2016-05-23 16:11:24: Created new database connection for urbackup/backup_client.db
2016-05-23 16:11:29: FileSrv: UDP: PING received… sending PONG. Delay=302ms
2016-05-23 16:11:59: urbackupserver: No available slots… starting new Worker
2016-05-23 16:11:59: ClientService cmd: #Ilg5naLxpfyjLuIWABJnw#ADD IDENTITY
2016-05-23 16:11:59: rc=0 hasError=true state=0
2016-05-23 16:11:59: ClientService cmd: #Ilg5naLxpfyjLuIWABJnw#GET CHALLENGE
2016-05-23 16:11:59: rc=0 hasError=true state=0

2

Some more things I have tried.

1 - Stopped client
2 - On client removed server_idents.txt file from /var/urbackup
3 - Waited for 5+ minutes
4 - Restarted the client service

Did not help. Urbackup server process has died.
[root@ILOakbVmUrbackup01 ~]# ps aux | grep urback
root 30833 0.0 0.0 103304 904 pts/1 S+ 12:04 0:00 grep urback

Server Log

2016-05-23 12:02:24: New Backupclient: ILOakbVmAPIServer

Client Log

2016-05-23 17:01:14: Loaded -fileserv- plugin
2016-05-23 17:01:14: Loaded -fsimageplugin- plugin
2016-05-23 17:01:14: Loaded -cryptoplugin- plugin
2016-05-23 17:01:14: Created new database connection for urbackup/backup_client.db
2016-05-23 17:01:14: urbackupserver: Server started up sucessfully!
2016-05-23 17:01:14: FileSrv: Info: retval 0
2016-05-23 17:01:14: FileSrv: Info: retval 0
2016-05-23 17:01:14: FileSrv: Info: Window size=458752
2016-05-23 17:01:14: Started UrBackupClient Backend…
2016-05-23 17:01:14: FileSrv: Binding udp socket at port 35622…
2016-05-23 17:01:14: FileSrv: done.
2016-05-23 17:01:14: FileSrv: Servername: -ILOakbVmAPIServer-
2016-05-23 17:01:14: FileSrv: Server started up sucessfully
2016-05-23 17:01:14: FileSrv: UDP Thread startet
2016-05-23 17:01:15: Looking for old Sessions… 0 sessions
2016-05-23 17:01:15: Internet only mode not enabled. Waiting for local server for 3:00…
2016-05-23 17:01:15: Created new database connection for urbackup/backup_client.db
2016-05-23 17:01:54: FileSrv: UDP: PING received… sending PONG. Delay=44ms
2016-05-23 17:02:24: urbackupserver: No available slots… starting new Worker
2016-05-23 17:02:24: ClientService cmd: #Ilg5naLxpfyjLuIWABJnw#ADD IDENTITY
2016-05-23 17:02:24: rc=0 hasError=true state=0
2016-05-23 17:02:24: ClientService cmd: #Ilg5naLxpfyjLuIWABJnw#GET CHALLENGE
2016-05-23 17:02:24: rc=0 hasError=true state=0
2016-05-23 17:04:15: Internet mode is not enabled.

3

More things I have done. None have worked yet.

Just to show that urbackup is running…
[root@ILOakbVmUrbackup01 urbackup]# ps aux | grep urback
urbackup 31366 0.0 0.1 432680 9920 ? Sl 13:20 0:00 /usr/sbin/urbackup_srv --daemon --plugin /usr/lib64/liburbackupserver_cryptoplugin.so --plugin /usr/lib64/liburbackupserver_fsimageplugin.so --plugin /usr/lib64/liburbackupserver.so --http_root /var/urbackup/www --workingdir /var --snapshot_helper /usr/bin/urbackup_snapshot_helper --plugin /usr/lib64/liburbackupserver_httpserver.so --port 55413 --logfile /var/log/urbackup.log --loglevel debug --http_port 55414 --pidfile /var/run/urbackup_srv.pid --user urbackup --broadcast_interfaces eth1

Now to verify that Urbackup is listening.
[root@ILOakbVmUrbackup01 urbackup]# tcpdump -i eth1 port 35623 and port 35622
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth1, link-type EN10MB (Ethernet), capture size 65535 bytes
14:23:03.895565 IP x.y.z.125.35623 > 255.255.255.255.35622: UDP, length 1
14:23:53.929516 IP x.y.z.125.35623 > 255.255.255.255.35622: UDP, length 1
14:23:54.143197 IP x.y.z.73.35622 > x.y.z.125.35623: UDP, length 19
^C
3 packets captured
3 packets received by filter
0 packets dropped by kernel

After the client and server talk to each other as you can see from above, the server process promptly dies.
[root@ILOakbVmUrbackup01 urbackup]# ps aux | grep urback
root 31874 0.0 0.0 103304 904 pts/0 S+ 14:24 0:00 grep urback

Still looking for a solution. Not sure where the problem lies though. The server and client are on the same subnet, they can ping each other and ssh to each other.

Going to stop iptables next to see if that fixes the problem.

Wes

4

Last of what I have tried today.

1 - Removed Urbackup client, deleted the /var/urbackup directory on the client. Reinstalled the client, started it. Urbackup server process died when the client attempted to connect. Looked in the /var/urbackup directory and there was a server_ident.txt file with the right key.
2 - Stopped iptables on both server and a client.
3 - Rebooted server.
4 - Used strace on server, got the following output when client attempted to connect.
poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)
poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)
poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)
poll([{fd=22, events=POLLIN}], 1, 1000 <unfinished …>
+++ killed by SIGABRT +++

Only thing I can think of to do is build the server from source with debug info. Put it in place and run via the debugger.

Anyone have another idea?

Thanks,

Wes

5

That might be the way to go. Since it is SIGABRT you may also get some info if you run it in foreground and not as daemon.

Running it in gdb is simple: start_urbackup_server --run_in_gdb (Then bt once it aborts).

6

Compiled Urback Server version (1.4.14) from source on CentOS 6.6.

Here is what I get when the client tries to connect:

2016-05-25 12:29:08: Created new database connection for urbackup/backup_server.db
2016-05-25 12:30:06: New Backupclient: ILOakbVmAPIServer
urbackup_srv: /usr/include/cryptopp/misc.h:304: void CryptoPP::memcpy_s(void*, size_t, const void*, size_t): Assertion `dest != __null’ failed.

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffcffff700 (LWP 16361)]
0x00007ffff6eba625 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install urbackup-server-1.4.14-3.1.x86_64

(gdb) bt
#0 0x00007ffff6eba625 in raise () from /lib64/libc.so.6
#1 0x00007ffff6ebbe05 in abort () from /lib64/libc.so.6
#2 0x00007ffff6eb374e in __assert_fail_base () from /lib64/libc.so.6
#3 0x00007ffff6eb3810 in __assert_fail () from /lib64/libc.so.6
#4 0x00007ffff661c9b4 in CryptoPP::memcpy_s(void*, unsigned long, void const*, unsigned long)
() from /usr/lib64/liburbackupserver_cryptoplugin.so
#5 0x00007ffff614e6af in CryptoPP::AlgorithmParametersBase::GetVoidValue(char const*, std::type_info const&, void*) const () from /usr/lib64/libcryptopp.so.6
#6 0x00007ffff61d4128 in CryptoPP::StringStore::StoreInitialize(CryptoPP::NameValuePairs const&) () from /usr/lib64/libcryptopp.so.6
#7 0x00007ffff662b1ef in CryptoPP::StringSource::StringSource(unsigned char const*, unsigned l—Type to continue, or q to quit—
ong, bool, CryptoPP::BufferedTransformation*) ()
from /usr/lib64/liburbackupserver_cryptoplugin.so
#8 0x00007ffff6620212 in CryptoFactory::signData(std::basic_string<char, std::char_traits, std::allocator > const&, std::basic_string<char, std::char_traits, std::allocator > const&, std::basic_string<char, std::char_traits, std::allocator >&) ()
from /usr/lib64/liburbackupserver_cryptoplugin.so
#9 0x00007ffff58da6aa in BackupServerGet::authenticatePubKey() ()
from /usr/lib64/liburbackupserver.so
#10 0x00007ffff58f152c in BackupServerGet::operator()() ()
from /usr/lib64/liburbackupserver.so
#11 0x0000000000449b25 in CPoolThread::operator() (this=0x7fffd40020b0) at ThreadPool.cpp:53
—Type to continue, or q to quit—
#12 0x00000000004139e9 in thread_helper_f (t=) at Server.cpp:1312
#13 0x00007ffff7223a51 in start_thread () from /lib64/libpthread.so.0
#14 0x00007ffff6f7093d in clone () from /lib64/libc.so.6

Not sure what I am going to try next. Possibly down grade the server to 1.4.12 as that is running in the lab with no issues.

Wes

7

Could be an issue with the crypto++ package (probably same as Centos 6.7 client Crash cryptopp/misc.h:304 ). Maybe compile that from source as well?