Ubuntu 18.04, Duplicati Service did not start anymore

PanPan · February 25, 2020, 6:46am

Hallo,

My Duplicati Setup suddently stopped working, now the server did not come up, even after a server reboot.

duplicati.service - Duplicati web-server
Loaded: loaded (/lib/systemd/system/duplicati.service; enabled; vendor preset: enabled)
Active: deactivating (final-sigkill) (Result: exit-code) since Tue 2020-02-25 07:37:17 CET; 5min ago
Process: 30855 ExecStart=/usr/bin/duplicati-server $DAEMON_OPTS (code=exited, status=200/CHDIR)
Main PID: 30855 (code=exited, status=200/CHDIR)
Tasks: 2 (limit: 4915)
CGroup: /system.slice/duplicati.service
└─26903 /usr/bin/mono-sgen /usr/lib/duplicati/Duplicati.Server.exe --webservice-port=8200 --webservice-interface=any

Feb 25 07:37:17 ERGSTAT01 duplicati-server[30855]: Unable to start up, perhaps another process is already running?
Feb 25 07:37:17 ERGSTAT01 duplicati-server[30855]: Error message: System.Exception: The lock file was locked, but the locking process di
Feb 25 07:37:17 ERGSTAT01 duplicati-server[30855]: at Duplicati.Server.SingleInstance…ctor (System.String basefolder) [0x00259] in <b
Feb 25 07:37:17 ERGSTAT01 duplicati-server[30855]: at Duplicati.Server.Program.RealMain (System.String _args) [0x00307] in <be73c239
Feb 25 07:37:17 ERGSTAT01 systemd[1]: duplicati.service: Main process exited, code=exited, status=200/CHDIR
Feb 25 07:38:47 ERGSTAT01 systemd[1]: duplicati.service: State ‘stop-sigterm’ timed out. Killing.
Feb 25 07:38:47 ERGSTAT01 systemd[1]: duplicati.service: Killing process 26903 (Threadpool work) with signal SIGKILL.
Feb 25 07:40:17 ERGSTAT01 systemd[1]: duplicati.service: Processes still around after SIGKILL. Ignoring.
Feb 25 07:41:47 ERGSTAT01 systemd[1]: duplicati.service: State ‘stop-final-sigterm’ timed out. Killing.
Feb 25 07:41:47 ERGSTAT01 systemd[1]: duplicati.service: Killing process 26903 (Threadpool work) with signal SIGKILL.
lines 1-19/19 (END)

I can not find the specific process.
Maybe you can tell me where

the log file or duplicati logs are stored ?

drwtsn32 · February 25, 2020, 11:47am

What does this show?

$ ps ax | grep -i duplicati

Also, right after running that do this again and show the output:

$ sudo systemctl status duplicati

PanPan · February 25, 2020, 12:11pm

drwtsn32 · February 25, 2020, 12:40pm

That CHDIR error is interesting. What does this show?

$ sudo cat /lib/systemd/system/duplicati.service

drwtsn32 · February 25, 2020, 12:49pm

Maybe try manually deleting the lock file:

(assuming you are using default location for systemd service)

$ sudo rm /root/.config/Duplicati/control_dir_v2/lock_v2

Then try starting Duplicati again.

PanPan · February 25, 2020, 1:43pm

Hello,

Thanks for your help !
I deleted the lock file. Please see the images.

drwtsn32 · February 25, 2020, 2:29pm

hmm, systemctl says it is active. But it couldn’t bind to 8200. Usually that means another instance is running.

Can you do this again to confirm:

$ ps ax | grep -i duplicati

Also try this:

$ sudo netstat -a -n -p | grep 'LISTEN.*mono-sgen'

PanPan · February 25, 2020, 3:40pm

Thanks. Sure

drwtsn32 · February 25, 2020, 5:45pm

Can you do this to see which process has claimed port 8200?

$ sudo netstat -a -n -p | grep '8200.*LISTEN'

PanPan · February 26, 2020, 6:11am

Hm, really strange. I cant find an real process !?

drwtsn32 · February 26, 2020, 6:45am

Hmm, confusing. If you’re using sudo you should be able to see the PID. I’m not sure what’s going on here.

Does this command show you the process name/PID?

$ sudo lsof -i :8200

PanPan · February 26, 2020, 8:23am

Hmh.
Sorry no output from the lsof command.

Maybe I can change the Port the testing purpose ?

PanPan · February 26, 2020, 10:22am

Crazy.
apt-get update and upgrade, reboot.

Now it seems to work now…

drwtsn32 · February 26, 2020, 1:21pm

Thanks for following up. Glad a reboot seemed to clear up your issue.

Only thing I could think of is that maybe it was a zombie process, but I believe should have still been able to see the ‘defunct’ process name when running lsof or netstat with sudo.

ts678 · February 26, 2020, 2:41pm

I suppose it’s possible some user of that port passed through and left before lsof saw it.

Local port numbers are usually automatically allocated, but I can force 8200 use with nc:

-p source_port
Specifies the source port nc should use, subject to privilege restrictions and availability.

This example will use that to www.duplicati.com just to create a connection that interferes:

# netstat -a -n -p | grep -w 8200
# 

$ duplicati-server
(starts and stays)

# netstat -a -n -p | grep -w 8200
tcp        0      0 0.0.0.0:8200            0.0.0.0:*               LISTEN      17118/mono-sgen 
tcp        0      0 127.0.0.1:52734         127.0.0.1:8200          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:52732         127.0.0.1:8200          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:8200          127.0.0.1:52736         ESTABLISHED 17118/mono-sgen 
tcp        0      0 127.0.0.1:8200          127.0.0.1:52730         ESTABLISHED 17118/mono-sgen 
tcp        0      0 127.0.0.1:8200          127.0.0.1:52722         ESTABLISHED 17118/mono-sgen 
tcp        0      0 127.0.0.1:52726         127.0.0.1:8200          FIN_WAIT2   -               
tcp        0      0 127.0.0.1:52718         127.0.0.1:8200          TIME_WAIT   -               
tcp        0      0 127.0.0.1:52722         127.0.0.1:8200          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:52728         127.0.0.1:8200          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:8200          127.0.0.1:52728         ESTABLISHED 17118/mono-sgen 
tcp        0      0 127.0.0.1:52720         127.0.0.1:8200          TIME_WAIT   -               
tcp        1      0 127.0.0.1:8200          127.0.0.1:52726         CLOSE_WAIT  17118/mono-sgen 
tcp        0      0 127.0.0.1:52730         127.0.0.1:8200          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:52736         127.0.0.1:8200          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:8200          127.0.0.1:52732         ESTABLISHED 17118/mono-sgen 
tcp        0      0 127.0.0.1:8200          127.0.0.1:52734         ESTABLISHED 17118/mono-sgen 
# 

(Ctrl-C duplicati-server)

# netstat -a -n -p | grep -w 8200
tcp        0      0 127.0.0.1:8200          127.0.0.1:52754         TIME_WAIT   -               
tcp        0      0 127.0.0.1:8200          127.0.0.1:52738         TIME_WAIT   -               
# 

(repeat that until clear)
# netstat -a -n -p | grep -w 8200
# 

(set up interference by deliberately taking local port 8200)

$ host www.duplicati.com
www.duplicati.com has address 139.59.135.67
$ nc -p 8200 139.59.135.67 443
(starts and sits awhile)

# netstat -a -n -p | grep -w 8200
tcp        0      0 192.168.0.106:8200      139.59.135.67:443       ESTABLISHED 17187/nc        
# 

$ duplicati-server
A serious error occurred in Duplicati: System.Exception: Unable to open a socket for listening, tried ports: 8200
  at Duplicati.Server.WebServer.Server..ctor (System.Collections.Generic.IDictionary`2[TKey,TValue] options) [0x00302] in <be73c239d77d4180b5147067144fc237>:0 
  at Duplicati.Server.Program.RealMain (System.String[] _args) [0x00674] in <be73c239d77d4180b5147067144fc237>:0 
$ 

If /usr/bin/duplicati were run instead of /usr/bin/duplicati-server, it would have found 8200 busy and taken 8300

# netstat -a -n -p | grep -w 8300
tcp        0      0 0.0.0.0:8300            0.0.0.0:*               LISTEN      17223/mono-sgen 
tcp        0      0 127.0.0.1:8300          127.0.0.1:56528         ESTABLISHED 17223/mono-sgen 
tcp        0      0 127.0.0.1:8300          127.0.0.1:56526         ESTABLISHED 17223/mono-sgen 
tcp        0      0 127.0.0.1:56508         127.0.0.1:8300          TIME_WAIT   -               
tcp        0      0 127.0.0.1:56530         127.0.0.1:8300          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:56506         127.0.0.1:8300          TIME_WAIT   -               
tcp        0      0 127.0.0.1:8300          127.0.0.1:56530         ESTABLISHED 17223/mono-sgen 
tcp        0      0 127.0.0.1:8300          127.0.0.1:56516         ESTABLISHED 17223/mono-sgen 
tcp        0      0 127.0.0.1:56512         127.0.0.1:8300          TIME_WAIT   -               
tcp        0      0 127.0.0.1:56522         127.0.0.1:8300          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:56528         127.0.0.1:8300          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:8300          127.0.0.1:56498         TIME_WAIT   -               
tcp        0      0 127.0.0.1:56510         127.0.0.1:8300          TIME_WAIT   -               
tcp        0      0 127.0.0.1:8300          127.0.0.1:56532         ESTABLISHED 17223/mono-sgen 
tcp        0      0 127.0.0.1:56526         127.0.0.1:8300          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:56532         127.0.0.1:8300          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:56514         127.0.0.1:8300          ESTABLISHED 17223/mono-sgen 
tcp        0      0 127.0.0.1:8300          127.0.0.1:56514         ESTABLISHED 17223/mono-sgen 
tcp        0      0 127.0.0.1:8300          127.0.0.1:56522         ESTABLISHED 17223/mono-sgen 
tcp        0      0 127.0.0.1:56500         127.0.0.1:8300          TIME_WAIT   -               
tcp        0      0 127.0.0.1:56516         127.0.0.1:8300          ESTABLISHED 23234/firefox   
tcp        0      0 127.0.0.1:8300          127.0.0.1:56502         TIME_WAIT   -               
tcp        0      0 127.0.0.1:56504         127.0.0.1:8300          TIME_WAIT   -               
#

If you look at the ports in the left hand column, you can see how those that aren’t 8300 are seemingly random. If some other program was dynamically assigned port 8200 even to connect outbound (as in example), it might have prevented the Duplicati server from starting, or relocated the TrayIcon variant.

I’m not familiar with the HTTP server, but possibly this is where that port conflict was initially detected:

github.com

duplicati/httpserver/blob/35eae1fe7df51668f3f09d538260804056dd9219/HttpServer/HttpListenerBase.cs#L179


      
          /// <summary>

          /// Start listen for new connections

          /// </summary>

          /// <param name="backlog">Number of connections that can stand in a queue to be accepted.</param>

          /// <exception cref="InvalidOperationException">Listener have already been started.</exception>

          public void Start(int backlog)

          {

              if (_listener != null)

                  throw new InvalidOperationException("Listener have already been started.");

          

              _listener = new TcpListener(_address, _port);

              _listener.Start(backlog);

              Interlocked.Increment(ref _pendingAccepts);

              _listener.BeginAcceptSocket(OnAccept, null);

          }

          

          /// <summary>

          /// Gets currently used port.

          /// </summary>

          public int Port

          {

TcpListener Class doesn’t say much (or give control of) low-level socket options that are being used.

TL;DR is this might have been a conflict with an Ephemeral port that got 8200 and used it for awhile.