Error: too many open files

Christoph · 3 September 2020 19:49

@gchen I’m still stuck with this issue. Not a single check command has been completed because of this. Allthough I am inclined to believe that pCloud’s webdav interface is not exactly making things better, It seems clear that the too many open files problem is a local problem so that even if pCloud is creating some errors, duplicacy is also somehow failing in handling these.

It also seems likely that this is a duplicacy problem, because I have been seeing this very same problem on two different machines, one Ubuntu 18.04 server and now on a freshly installed Debian 10 machine (OpenMediaVault). I have not modified the Debian OS (all my apps are running in various docker containers) so I don’t see how this is not a duplicacy bug or design fault…

2020-09-02 23:34:58.996 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/ALPHA_C/252' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/ALPHA_C/252: EOF)
2020-09-02 23:35:23.063 TRACE WEBDAV_RETRY URL request 'MKCOL snapshots/ALPHA_C' returned an error (Mkcol https://webdav.pcloud.com/Backup/Duplicacy/snapshots/ALPHA_C: EOF)
2020-09-02 23:35:49.455 WARN DOWNLOAD_FILE_CACHE Failed to add the file snapshots/ALPHA_C/272 to the snapshot cache: open /tmp/.duplicacy-web/repositories/localhost/all/.duplicacy/cache/pcloud/snapshots/ALPHA_C/272.pcwrzhfe.tmp: too many open files
2020-09-02 23:35:49.612 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/ALPHA_C/273' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/ALPHA_C/273: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: dial udp 1.1.1.1:53: socket: too many open files)
2020-09-02 23:35:50.483 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/ALPHA_C/273' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/ALPHA_C/273: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: dial udp 1.1.1.1:53: socket: too many open files)
2020-09-02 23:35:52.041 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/ALPHA_C/273' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/ALPHA_C/273: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: dial udp 1.1.1.1:53: socket: too many open files)
2020-09-02 23:35:55.082 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/ALPHA_C/273' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/ALPHA_C/273: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: dial udp 1.1.1.1:53: socket: too many open files)
2020-09-02 23:36:00.451 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/ALPHA_C/273' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/ALPHA_C/273: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: dial udp 1.1.1.1:53: socket: too many open files)
2020-09-02 23:36:09.710 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/ALPHA_C/273' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/ALPHA_C/273: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: dial udp 1.1.1.1:53: socket: too many open files)
2020-09-02 23:36:27.985 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/ALPHA_C/273' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/ALPHA_C/273: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: dial udp 1.1.1.1:53: socket: too many open files)
2020-09-02 23:37:09.796 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/ALPHA_C/273' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/ALPHA_C/273: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: dial udp 1.1.1.1:53: socket: too many open files)
2020-09-02 23:39:14.283 ERROR SNAPSHOT_INFO Failed to get the information on the snapshot ALPHA_C at revision 273: Maximum backoff reached
Failed to get the information on the snapshot ALPHA_C at revision 273: Maximum backoff reached

saspus · 3 September 2020 20:54

Not exactly helpful comment but this is exactly why Duplicacy should drop support for file sharing storage backends. They are not designed for bulk storage and will fail in weird in wonderful way — exemplified by this topic — and ultimately result is user frustration and extra futile support workload for Acrosync.

More organized thoughts on this here: (Newbie) Backup entire machine?

Christoph · 3 September 2020 23:41

I’m willing to admit that I wasted - I think it was 500 USD - when buying 4TB of lifetime storage from pCloud; I was not aware of the differences that you explain so well in the other post… But are you saying that only pCloud is to blame? I don’t understand the logs 100% but it seems clear to me that duplicacy is not handling whatever problems pCloud is having properly, no?

saspus · 3 September 2020 23:53

I did not watch the thread too carefully but 401(unauthorized) and TLS handshake timeout is fairly certainly either service issues or their anti-abuse measures. Either way not good for intended purpose.

Duplicacy should keep trying to back off and retry with increasing interval — and maybe it does fail to do so in some cases but it’s too late anyway. Service has already face planted.

The too many open files does look like client side issue — perhaps you are hitting limit on max open files? You can run lsof to see who has holding what handles and then act accordingly (murder the offending process or report Duplicacy bug or increase handles limit). Maybe indeed there is a bug handling failed connections and Duplicacy is not letting go the orphaned connections?

gchen · 4 September 2020 01:16

What is the TTL of webdav.pcloud.com on your machine? On mine it is 7200 seconds. If this TTL is too small there will be too many DNS requests.

$ dig +nocmd +noall +answer webdav.pcloud.com
webdav.pcloud.com.	7199	IN	A	74.120.8.227

I think you should keep running lsof once Duplicacy starts. Maybe write a script to save the output of lsof to a file every minute. You should be watching all file descriptors opened by the Duplicacy CLI, not the web GUI. If the list of file descriptors keeps grow, it may be fairly obvious what is leaking.

Christoph · 4 September 2020 14:10

Aaah, TTL! that is the answer to this question:

Anyway: a couple of hours ago, I was also getting 7200. But now (after having started by check command on the web-ui) I’m getting slightly less:

$ dig +nocmd +noall +answer webdav.pcloud.com
webdav.pcloud.com.      6188    IN      A       74.120.8.227

And now, I couple of minutes later, it’s less again:

$ dig +nocmd +noall +answer webdav.pcloud.com
webdav.pcloud.com.      5862    IN      A       74.120.8.227

I’m assuming that this is reflecting the countdown of those two hours that was triggered when duplicacy queried the DNS.

As suggested, I am also monitoring which files duplicacy has opened. I did the following:

$ ps aux | grep duplicacy
root       959  0.0  0.2 196800 21184 ?        Ssl  Aug25   3:05 /usr/bin/duplicacy-web
root     28590  5.3  0.5 126696 40192 ?        Sl   15:30   0:01 /.duplicacy-web/bin/duplicacy_linux_x64_2.6.1 -log -v check -storage pcloud -a -tabular
root     29241  0.0  0.0   6204   888 pts/4    S+   15:30   0:00 grep duplicacy

Then I used the pid of the CLI process to do

$ lsof -p 28590 -r300 >> /zfs/NAS/christoph/duplicacy_open_files.log &

(I thought logging every five minutes would be sufficient.)

So currently I’m getting:

COMMAND     PID USER   FD      TYPE    DEVICE SIZE/OFF      NODE NAME
duplicacy 28590 root  cwd       DIR      0,50       60        16 /tmp/.duplicacy-web/repositories/localhost/all
duplicacy 28590 root  rtd       DIR       8,1     4096         2 /
duplicacy 28590 root  txt       REG       8,1 31740199  13369359 /.duplicacy-web/bin/duplicacy_linux_x64_2.6.1
duplicacy 28590 root    0r      CHR       1,3      0t0         6 /dev/null
duplicacy 28590 root    1w     FIFO      0,13      0t0 104332902 pipe
duplicacy 28590 root    2w      CHR       1,3      0t0         6 /dev/null
duplicacy 28590 root    3u     sock       0,9      0t0 104332951 protocol: TCP
duplicacy 28590 root    4u  a_inode      0,14        0     11185 [eventpoll]
duplicacy 28590 root    5u     sock       0,9      0t0 104333609 protocol: TCP
duplicacy 28590 root    6u     IPv4 104770091      0t0       TCP server.lan:42440->api13.pcloud.com:https (ESTABLISHED)

I’ll get back once the process has failed.

This is the kind of thing I am suspecting, but I’m unable to trace down that kind of stuff by myself. So let’s see what that log will reveal.

Christoph · 4 September 2020 21:06

So, here we go. It didn’t take very long until things started piling up. I’ll give you the last “ordinary” log and then the one five minutes later and another five minutes later (to stay within the max character limit per post I’m cutting out repetitive lines):

COMMAND     PID USER   FD      TYPE    DEVICE SIZE/OFF      NODE NAME
duplicacy 28590 root  cwd       DIR      0,50       60        16 /tmp/.duplicacy-web/repositories/localhost/all
duplicacy 28590 root  rtd       DIR       8,1     4096         2 /
duplicacy 28590 root  txt       REG       8,1 31740199  13369359 /.duplicacy-web/bin/duplicacy_linux_x64_2.6.1
duplicacy 28590 root    0r      CHR       1,3      0t0         6 /dev/null
duplicacy 28590 root    1w     FIFO      0,13      0t0 104332902 pipe
duplicacy 28590 root    2w      CHR       1,3      0t0         6 /dev/null
duplicacy 28590 root    3u     sock       0,9      0t0 104332951 protocol: TCP
duplicacy 28590 root    4u  a_inode      0,14        0     11185 [eventpoll]
duplicacy 28590 root    5u     sock       0,9      0t0 104333609 protocol: TCP
duplicacy 28590 root    6u     IPv4 104856773      0t0       TCP server.lan:43182->api13.pcloud.com:https (ESTABLISHED)
=======
COMMAND     PID USER   FD      TYPE    DEVICE SIZE/OFF      NODE NAME
duplicacy 28590 root  cwd       DIR      0,50       60        16 /tmp/.duplicacy-web/repositories/localhost/all
duplicacy 28590 root  rtd       DIR       8,1     4096         2 /
duplicacy 28590 root  txt       REG       8,1 31740199  13369359 /.duplicacy-web/bin/duplicacy_linux_x64_2.6.1
duplicacy 28590 root    0r      CHR       1,3      0t0         6 /dev/null
duplicacy 28590 root    1w     FIFO      0,13      0t0 104332902 pipe
duplicacy 28590 root    2w      CHR       1,3      0t0         6 /dev/null
duplicacy 28590 root    3u     sock       0,9      0t0 104332951 protocol: TCP
duplicacy 28590 root    4u  a_inode      0,14        0     11185 [eventpoll]
duplicacy 28590 root    5u     sock       0,9      0t0 104333609 protocol: TCP
duplicacy 28590 root    6u     IPv4 104880962      0t0       TCP server.lan:50474->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root    7u     IPv4 104880999      0t0       TCP server.lan:50526->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root    8u     IPv4 104881032      0t0       TCP server.lan:50532->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root    9u     IPv4 104881785      0t0       TCP server.lan:50550->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   10u     IPv4 104881082      0t0       TCP server.lan:50576->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   11u     IPv4 104881116      0t0       TCP server.lan:50634->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   12u     IPv4 104881146      0t0       TCP server.lan:50708->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   13u     IPv4 104883139      0t0       TCP server.lan:51406->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   14u     IPv4 104885905      0t0       TCP server.lan:51414->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   15u     IPv4 104883169      0t0       TCP server.lan:51450->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   16u     IPv4 104885917      0t0       TCP server.lan:51500->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   17u     IPv4 104885930      0t0       TCP server.lan:51540->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   18u     IPv4 104886288      0t0       TCP server.lan:51584->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   19u     IPv4 104885975      0t0       TCP server.lan:51588->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   20u     IPv4 104885987      0t0       TCP server.lan:51590->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   21u     IPv4 104885999      0t0       TCP server.lan:51618->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   22u     IPv4 104886322      0t0       TCP server.lan:51676->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   23u     IPv4 104886354      0t0       TCP server.lan:51698->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   24u     IPv4 104886450      0t0       TCP server.lan:51748->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   25u     IPv4 104886115      0t0       TCP server.lan:51776->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   26u     IPv4 104886505      0t0       TCP server.lan:51794->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   27u     IPv4 104886178      0t0       TCP server.lan:51864->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   28u     IPv4 104886515      0t0       TCP server.lan:51880->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   29u     IPv4 104886209      0t0       TCP server.lan:51930->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   30u     IPv4 104888482      0t0       TCP server.lan:51958->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   31u     IPv4 104888490      0t0       TCP server.lan:51962->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   32u     IPv4 104888495      0t0       TCP server.lan:51980->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   33u     IPv4 104888528      0t0       TCP server.lan:52042->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   34u     IPv4 104888543      0t0       TCP server.lan:52058->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   35u     IPv4 104889426      0t0       TCP server.lan:52072->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   36u     IPv4 104889429      0t0       TCP server.lan:52110->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   37u     IPv4 104888612      0t0       TCP server.lan:52132->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   38u     IPv4 104889468      0t0       TCP server.lan:52144->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   39u     IPv4 104888620      0t0       TCP server.lan:52146->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   40u     IPv4 104888637      0t0       TCP server.lan:52208->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   41u     IPv4 104889564      0t0       TCP server.lan:52240->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   42u     IPv4 104889570      0t0       TCP server.lan:52248->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   43u     IPv4 104888691      0t0       TCP server.lan:52296->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   44u     IPv4 104888693      0t0       TCP server.lan:52300->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   45u     IPv4 104889587      0t0       TCP server.lan:52326->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   46u     IPv4 104888708      0t0       TCP server.lan:52328->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   47u     IPv4 104888728      0t0       TCP server.lan:52378->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   48u     IPv4 104889017      0t0       TCP server.lan:52404->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   49u     IPv4 104890227      0t0       TCP server.lan:52454->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   50u     IPv4 104889104      0t0       TCP server.lan:52482->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   51u     IPv4 104889114      0t0       TCP server.lan:52502->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   52u     IPv4 104890250      0t0       TCP server.lan:52510->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   53u     IPv4 104889128      0t0       TCP server.lan:52556->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   54u     IPv4 104890305      0t0       TCP server.lan:52576->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   55u     IPv4 104889175      0t0       TCP server.lan:52594->api13.pcloud.com:https (ESTABLISHED)
duplicacy 28590 root   56u     IPv4 104890324      0t0       TCP server.lan:52646->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   57u     IPv4 104889207      0t0       TCP server.lan:52666->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root   58u     IPv4 104890336      0t0       TCP server.lan:52688->api13.pcloud.com:https (ESTABLISHED)
duplicacy 28590 root   59u     IPv4 104891458      0t0       TCP server.lan:52844->api13.pcloud.com:https (ESTABLISHED)
=======
COMMAND     PID USER   FD      TYPE    DEVICE SIZE/OFF      NODE NAME
duplicacy 28590 root  cwd       DIR      0,50       60        16 /tmp/.duplicacy-web/repositories/localhost/all
duplicacy 28590 root  rtd       DIR       8,1     4096         2 /
duplicacy 28590 root  txt       REG       8,1 31740199  13369359 /.duplicacy-web/bin/duplicacy_linux_x64_2.6.1
duplicacy 28590 root    0r      CHR       1,3      0t0         6 /dev/null
duplicacy 28590 root    1w     FIFO      0,13      0t0 104332902 pipe
duplicacy 28590 root    2w      CHR       1,3      0t0         6 /dev/null
duplicacy 28590 root    3u     sock       0,9      0t0 104332951 protocol: TCP
duplicacy 28590 root    4u  a_inode      0,14        0     11185 [eventpoll]
duplicacy 28590 root    5u     sock       0,9      0t0 104333609 protocol: TCP
duplicacy 28590 root    6u     sock       0,9      0t0 104880962 protocol: TCP
duplicacy 28590 root    7u     sock       0,9      0t0 104880999 protocol: TCP
duplicacy 28590 root    8u     sock       0,9      0t0 104881032 protocol: TCP
duplicacy 28590 root    9u     sock       0,9      0t0 104881785 protocol: TCP
duplicacy 28590 root   10u     sock       0,9      0t0 104881082 protocol: TCP
duplicacy 28590 root   11u     sock       0,9      0t0 104881116 protocol: TCP
duplicacy 28590 root   12u     sock       0,9      0t0 104881146 protocol: TCP
duplicacy 28590 root   13u     sock       0,9      0t0 104883139 protocol: TCP
duplicacy 28590 root   14u     sock       0,9      0t0 104885905 protocol: TCP
duplicacy 28590 root   15u     sock       0,9      0t0 104883169 protocol: TCP
duplicacy 28590 root   16u     sock       0,9      0t0 104885917 protocol: TCP
duplicacy 28590 root   17u     sock       0,9      0t0 104885930 protocol: TCP
duplicacy 28590 root   18u     sock       0,9      0t0 104886288 protocol: TCP
duplicacy 28590 root   19u     sock       0,9      0t0 104885975 protocol: TCP
duplicacy 28590 root   20u     sock       0,9      0t0 104885987 protocol: TCP
duplicacy 28590 root   21u     sock       0,9      0t0 104885999 protocol: TCP
duplicacy 28590 root   22u     sock       0,9      0t0 104886322 protocol: TCP
duplicacy 28590 root   23u     sock       0,9      0t0 104886354 protocol: TCP
duplicacy 28590 root   24u     sock       0,9      0t0 104886450 protocol: TCP
duplicacy 28590 root   25u     sock       0,9      0t0 104886115 protocol: TCP
duplicacy 28590 root   26u     sock       0,9      0t0 104886505 protocol: TCP
duplicacy 28590 root   27u     sock       0,9      0t0 104886178 protocol: TCP
duplicacy 28590 root   28u     sock       0,9      0t0 104886515 protocol: TCP
duplicacy 28590 root   29u     sock       0,9      0t0 104886209 protocol: TCP
duplicacy 28590 root   30u     sock       0,9      0t0 104888482 protocol: TCP
duplicacy 28590 root   31u     sock       0,9      0t0 104888490 protocol: TCP
duplicacy 28590 root   32u     sock       0,9      0t0 104888495 protocol: TCP
duplicacy 28590 root   33u     sock       0,9      0t0 104888528 protocol: TCP
duplicacy 28590 root   34u     sock       0,9      0t0 104888543 protocol: TCP
duplicacy 28590 root   35u     sock       0,9      0t0 104889426 protocol: TCP
duplicacy 28590 root   36u     sock       0,9      0t0 104889429 protocol: TCP
duplicacy 28590 root   37u     sock       0,9      0t0 104888612 protocol: TCP
duplicacy 28590 root   38u     sock       0,9      0t0 104889468 protocol: TCP
duplicacy 28590 root   39u     sock       0,9      0t0 104888620 protocol: TCP
.
.
[160 lines cut]
.
.
duplicacy 28590 root  200u     sock       0,9      0t0 104910169 protocol: TCP
duplicacy 28590 root  201u     sock       0,9      0t0 104910884 protocol: TCP
duplicacy 28590 root  202u     sock       0,9      0t0 104910197 protocol: TCP
duplicacy 28590 root  203u     sock       0,9      0t0 104910917 protocol: TCP
duplicacy 28590 root  204u     sock       0,9      0t0 104910939 protocol: TCP
duplicacy 28590 root  205u     sock       0,9      0t0 104910947 protocol: TCP
duplicacy 28590 root  206u     sock       0,9      0t0 104911036 protocol: TCP
duplicacy 28590 root  207u     sock       0,9      0t0 104911100 protocol: TCP
duplicacy 28590 root  208u     sock       0,9      0t0 104910633 protocol: TCP
duplicacy 28590 root  209u     sock       0,9      0t0 104911733 protocol: TCP
duplicacy 28590 root  210u     sock       0,9      0t0 104910656 protocol: TCP
duplicacy 28590 root  211u     sock       0,9      0t0 104910670 protocol: TCP
duplicacy 28590 root  212u     sock       0,9      0t0 104911782 protocol: TCP
duplicacy 28590 root  213u     sock       0,9      0t0 104910686 protocol: TCP
duplicacy 28590 root  214u     sock       0,9      0t0 104911792 protocol: TCP
duplicacy 28590 root  215u     sock       0,9      0t0 104911803 protocol: TCP
duplicacy 28590 root  216u     sock       0,9      0t0 104911878 protocol: TCP
duplicacy 28590 root  217u     sock       0,9      0t0 104911852 protocol: TCP
duplicacy 28590 root  218u     sock       0,9      0t0 104912913 protocol: TCP
duplicacy 28590 root  219u     IPv4 104912052      0t0       TCP server.lan:59000->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  220u     sock       0,9      0t0 104912060 protocol: TCP
duplicacy 28590 root  221u     sock       0,9      0t0 104912068 protocol: TCP
duplicacy 28590 root  222u     sock       0,9      0t0 104912071 protocol: TCP
duplicacy 28590 root  223u     sock       0,9      0t0 104913009 protocol: TCP
duplicacy 28590 root  224u     IPv4 104912126      0t0       TCP server.lan:59142->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  225u     sock       0,9      0t0 104913028 protocol: TCP
duplicacy 28590 root  226u     sock       0,9      0t0 104915012 protocol: TCP
duplicacy 28590 root  227u     IPv4 104915017      0t0       TCP server.lan:59180->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  228u     sock       0,9      0t0 104915033 protocol: TCP
duplicacy 28590 root  229u     sock       0,9      0t0 104913052 protocol: TCP
duplicacy 28590 root  230u     IPv4 104915061      0t0       TCP server.lan:59258->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  231u     sock       0,9      0t0 104913068 protocol: TCP
duplicacy 28590 root  232u     sock       0,9      0t0 104913161 protocol: TCP
duplicacy 28590 root  233u     IPv4 104915177      0t0       TCP server.lan:59340->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  234u     IPv4 104913181      0t0       TCP server.lan:59350->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  235u     IPv4 104913190      0t0       TCP server.lan:59384->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  236u     IPv4 104913199      0t0       TCP server.lan:59400->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  237u     sock       0,9      0t0 104915237 protocol: TCP
duplicacy 28590 root  238u     IPv4 104915246      0t0       TCP server.lan:59482->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  239u     sock       0,9      0t0 104915266 protocol: TCP
duplicacy 28590 root  240u     sock       0,9      0t0 104915277 protocol: TCP
duplicacy 28590 root  241u     sock       0,9      0t0 104915312 protocol: TCP
duplicacy 28590 root  242u     sock       0,9      0t0 104915323 protocol: TCP
duplicacy 28590 root  243u     IPv4 104915341      0t0       TCP server.lan:59570->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  244u     IPv4 104915363      0t0       TCP server.lan:59628->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  245u     sock       0,9      0t0 104915401 protocol: TCP
duplicacy 28590 root  246u     IPv4 104915423      0t0       TCP server.lan:59660->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  247u     IPv4 104915821      0t0       TCP server.lan:59674->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  248u     IPv4 104915832      0t0       TCP server.lan:59690->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  249u     sock       0,9      0t0 104916103 protocol: TCP
duplicacy 28590 root  250u     IPv4 104916112      0t0       TCP server.lan:59780->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  251u     sock       0,9      0t0 104916127 protocol: TCP
duplicacy 28590 root  252u     IPv4 104915883      0t0       TCP server.lan:59826->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  253u     IPv4 104915886      0t0       TCP server.lan:59840->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  254u     IPv4 104916175      0t0       TCP server.lan:59858->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  255u     IPv4 104915907      0t0       TCP server.lan:59878->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  256u     IPv4 104915932      0t0       TCP server.lan:59920->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  257u     IPv4 104915967      0t0       TCP server.lan:59950->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  258u     IPv4 104916278      0t0       TCP server.lan:59958->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  259u     IPv4 104916285      0t0       TCP server.lan:59984->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  260u     IPv4 104916293      0t0       TCP server.lan:60000->api13.pcloud.com:https (CLOSE_WAIT)
.
.
[50 lines cut]
.
.
duplicacy 28590 root  311u     IPv4 104919469      0t0       TCP server.lan:33076->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  312u     IPv4 104919476      0t0       TCP server.lan:33086->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  313u     IPv4 104921699      0t0       TCP server.lan:33124->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  314u     IPv4 104919518      0t0       TCP server.lan:33132->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  315u     IPv4 104919660      0t0       TCP server.lan:33280->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  316u     IPv4 104919667      0t0       TCP server.lan:33298->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  317u     IPv4 104921938      0t0       TCP server.lan:33338->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  318u     IPv4 104923150      0t0       TCP server.lan:33540->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  319u     IPv4 104922302      0t0       TCP server.lan:33590->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  320u     IPv4 104923194      0t0       TCP server.lan:33596->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  321u     IPv4 104923293      0t0       TCP server.lan:33688->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  322u     IPv4 104923319      0t0       TCP server.lan:33744->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  323u     IPv4 104923322      0t0       TCP server.lan:33748->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  324u     IPv4 104923354      0t0       TCP server.lan:33760->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  325u     IPv4 104922495      0t0       TCP server.lan:33778->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  326u     IPv4 104923401      0t0       TCP server.lan:33806->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  327u     IPv4 104922516      0t0       TCP server.lan:33832->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  328u     IPv4 104922530      0t0       TCP server.lan:33852->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  329u     IPv4 104923445      0t0       TCP server.lan:33908->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  330u     IPv4 104923497      0t0       TCP server.lan:33912->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  331u     IPv4 104922622      0t0       TCP server.lan:33914->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  332u     IPv4 104922632      0t0       TCP server.lan:33932->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  333u     IPv4 104923515      0t0       TCP server.lan:33966->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  334u     IPv4 104923521      0t0       TCP server.lan:33992->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  335u     IPv4 104923527      0t0       TCP server.lan:34002->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  336u     IPv4 104922744      0t0       TCP server.lan:34068->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  337u     IPv4 104923548      0t0       TCP server.lan:34078->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  338u     IPv4 104923554      0t0       TCP server.lan:34080->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  339u     IPv4 104922767      0t0       TCP server.lan:34092->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  340u     IPv4 104923579      0t0       TCP server.lan:34112->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  341u     IPv4 104922813      0t0       TCP server.lan:34142->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  342u     IPv4 104922822      0t0       TCP server.lan:34162->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  343u     IPv4 104922827      0t0       TCP server.lan:34216->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  344u     IPv4 104923708      0t0       TCP server.lan:34240->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  345u     IPv4 104922899      0t0       TCP server.lan:34242->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  346u     IPv4 104922917      0t0       TCP server.lan:34252->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  347u     IPv4 104924057      0t0       TCP server.lan:34262->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  348u     IPv4 104924216      0t0       TCP server.lan:34294->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  349u     IPv4 104924093      0t0       TCP server.lan:34322->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  350u     IPv4 104924099      0t0       TCP server.lan:34364->api13.pcloud.com:https (ESTABLISHED)
duplicacy 28590 root  351u     IPv4 104924249      0t0       TCP server.lan:34394->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  352u     IPv4 104924118      0t0       TCP server.lan:34404->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  353u     IPv4 104924262      0t0       TCP server.lan:34412->api13.pcloud.com:https (ESTABLISHED)
duplicacy 28590 root  354u     IPv4 104924129      0t0       TCP server.lan:34426->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  355u     IPv4 104924276      0t0       TCP server.lan:34444->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  356u     IPv4 104924323      0t0       TCP server.lan:34494->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  357u     IPv4 104925262      0t0       TCP server.lan:34540->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  358u     IPv4 104925325      0t0       TCP server.lan:34564->api13.pcloud.com:https (ESTABLISHED)
duplicacy 28590 root  359u     IPv4 104925330      0t0       TCP server.lan:34574->api13.pcloud.com:https (ESTABLISHED)
duplicacy 28590 root  360u     IPv4 104925338      0t0       TCP server.lan:34580->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 28590 root  361u     IPv4 104925343      0t0       TCP server.lan:34596->api13.pcloud.com:https (ESTABLISHED)

The number of open files then increases every five minutes. The last log before the command failed has over 1000 entries.

Does “CLOSE_WAIT” mean that @saspus was right about the orphaned connections?

gchen · 5 September 2020 04:08

This could have been fixed by this PR: Improve WebDAV performance by Jos635 · Pull Request #549 · gilbertchen/duplicacy · GitHub

I compiled a linux binary from this PR if you want to test it: https://acrosync.com/duplicacy/duplicacy_linux_x64_2.6.11

Christoph · 5 September 2020 14:34

Unfortunately, that did not change anything:

COMMAND     PID USER   FD      TYPE    DEVICE SIZE/OFF      NODE NAME
duplicacy 24909 root  cwd       DIR      0,50       60        16 /tmp/.duplicacy-web/repositories/localhost/all
duplicacy 24909 root  rtd       DIR       8,1     4096         2 /
duplicacy 24909 root  txt       REG       8,1 32295152  13371337 /.duplicacy-web/bin/duplicacy_linux_x64_2.6.1
duplicacy 24909 root    0r      CHR       1,3      0t0         6 /dev/null
duplicacy 24909 root    1w     FIFO      0,13      0t0 109290291 pipe
duplicacy 24909 root    2w      CHR       1,3      0t0         6 /dev/null
duplicacy 24909 root    3u     sock       0,9      0t0 109292422 protocol: TCP
duplicacy 24909 root    4u  a_inode      0,14        0     11185 [eventpoll]
duplicacy 24909 root    5u     sock       0,9      0t0 109292638 protocol: TCP
duplicacy 24909 root    6u     IPv4 109448525      0t0       TCP server.lan:47224->api13.pcloud.com:https (ESTABLISHED)
=======
COMMAND     PID USER   FD      TYPE    DEVICE SIZE/OFF      NODE NAME
duplicacy 24909 root  cwd       DIR      0,50       60        16 /tmp/.duplicacy-web/repositories/localhost/all
duplicacy 24909 root  rtd       DIR       8,1     4096         2 /
duplicacy 24909 root  txt       REG       8,1 32295152  13371337 /.duplicacy-web/bin/duplicacy_linux_x64_2.6.1
duplicacy 24909 root    0r      CHR       1,3      0t0         6 /dev/null
duplicacy 24909 root    1w     FIFO      0,13      0t0 109290291 pipe
duplicacy 24909 root    2w      CHR       1,3      0t0         6 /dev/null
duplicacy 24909 root    3u     sock       0,9      0t0 109292422 protocol: TCP
duplicacy 24909 root    4u  a_inode      0,14        0     11185 [eventpoll]
duplicacy 24909 root    5u     sock       0,9      0t0 109292638 protocol: TCP
duplicacy 24909 root    6u     IPv4 109466664      0t0       TCP server.lan:54928->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root    7u     IPv4 109466565      0t0       TCP server.lan:54980->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root    8u     IPv4 109466571      0t0       TCP server.lan:54990->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root    9u     IPv4 109466689      0t0       TCP server.lan:55016->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   10u     IPv4 109466588      0t0       TCP server.lan:55042->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   11u     IPv4 109466708      0t0       TCP server.lan:55058->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   12u     IPv4 109466711      0t0       TCP server.lan:55094->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   13u     IPv4 109466718      0t0       TCP server.lan:55152->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   14u     IPv4 109467706      0t0       TCP server.lan:55178->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   15u     IPv4 109466757      0t0       TCP server.lan:55196->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   16u     IPv4 109467714      0t0       TCP server.lan:55206->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   17u     IPv4 109466774      0t0       TCP server.lan:55232->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   18u     IPv4 109467745      0t0       TCP server.lan:55272->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   19u     IPv4 109466793      0t0       TCP server.lan:55324->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   20u     IPv4 109466801      0t0       TCP server.lan:55350->api13.pcloud.com:https (CLOSE_WAIT)
.
,
[60 lines ommitted]
.
.
duplicacy 24909 root   81u     IPv4 109472255      0t0       TCP server.lan:56990->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   82u     IPv4 109467611      0t0       TCP server.lan:57002->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   83u     IPv4 109467620      0t0       TCP server.lan:57044->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   84u     IPv4 109467632      0t0       TCP server.lan:57094->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   85u     IPv4 109467640      0t0       TCP server.lan:57116->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   86u     IPv4 109472330      0t0       TCP server.lan:57140->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   87u     IPv4 109472341      0t0       TCP server.lan:57156->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   88u     IPv4 109472345      0t0       TCP server.lan:57168->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   89u     IPv4 109472355      0t0       TCP server.lan:57186->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   90u     IPv4 109472370      0t0       TCP server.lan:57204->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root   91u     IPv4 109472816      0t0       TCP server.lan:57256->api13.pcloud.com:https (ESTABLISHED)
duplicacy 24909 root   92u     IPv4 109472416      0t0       TCP server.lan:57282->api13.pcloud.com:https (ESTABLISHED)
duplicacy 24909 root   93u     IPv4 109472840      0t0       TCP server.lan:57320->api13.pcloud.com:https (ESTABLISHED)
duplicacy 24909 root   94u     IPv4 109472846      0t0       TCP server.lan:57338->api13.pcloud.com:https (ESTABLISHED)
duplicacy 24909 root   95u     IPv4 109472848      0t0       TCP server.lan:57356->api13.pcloud.com:https (ESTABLISHED)
duplicacy 24909 root   96u     IPv4 109472461      0t0       TCP server.lan:57370->api13.pcloud.com:https (ESTABLISHED)
duplicacy 24909 root   97u     IPv4 109472868      0t0       TCP server.lan:57392->api13.pcloud.com:https (ESTABLISHED)
duplicacy 24909 root   98u     IPv4 109472885      0t0       TCP server.lan:57434->api13.pcloud.com:https (SYN_SENT)
=======
COMMAND     PID USER   FD      TYPE    DEVICE SIZE/OFF      NODE NAME
duplicacy 24909 root  cwd       DIR      0,50       60        16 /tmp/.duplicacy-web/repositories/localhost/all
duplicacy 24909 root  rtd       DIR       8,1     4096         2 /
duplicacy 24909 root  txt       REG       8,1 32295152  13371337 /.duplicacy-web/bin/duplicacy_linux_x64_2.6.1
duplicacy 24909 root    0r      CHR       1,3      0t0         6 /dev/null
duplicacy 24909 root    1w     FIFO      0,13      0t0 109290291 pipe
duplicacy 24909 root    2w      CHR       1,3      0t0         6 /dev/null
duplicacy 24909 root    3u     sock       0,9      0t0 109292422 protocol: TCP
duplicacy 24909 root    4u  a_inode      0,14        0     11185 [eventpoll]
duplicacy 24909 root    5u     sock       0,9      0t0 109292638 protocol: TCP
duplicacy 24909 root    6u     sock       0,9      0t0 109466664 protocol: TCP
duplicacy 24909 root    7u     sock       0,9      0t0 109466565 protocol: TCP
duplicacy 24909 root    8u     sock       0,9      0t0 109466571 protocol: TCP
duplicacy 24909 root    9u     sock       0,9      0t0 109466689 protocol: TCP
duplicacy 24909 root   10u     sock       0,9      0t0 109466588 protocol: TCP
duplicacy 24909 root   11u     sock       0,9      0t0 109466708 protocol: TCP
duplicacy 24909 root   12u     sock       0,9      0t0 109466711 protocol: TCP
duplicacy 24909 root   13u     sock       0,9      0t0 109466718 protocol: TCP
duplicacy 24909 root   14u     sock       0,9      0t0 109467706 protocol: TCP
duplicacy 24909 root   15u     sock       0,9      0t0 109466757 protocol: TCP
duplicacy 24909 root   16u     sock       0,9      0t0 109467714 protocol: TCP
duplicacy 24909 root   17u     sock       0,9      0t0 109466774 protocol: TCP
duplicacy 24909 root   18u     sock       0,9      0t0 109467745 protocol: TCP
duplicacy 24909 root   19u     sock       0,9      0t0 109466793 protocol: TCP
duplicacy 24909 root   20u     sock       0,9      0t0 109466801 protocol: TCP
.
.
[250 lines ommitted]
.
.
duplicacy 24909 root  271u     sock       0,9      0t0 109486234 protocol: TCP
duplicacy 24909 root  272u     sock       0,9      0t0 109486243 protocol: TCP
duplicacy 24909 root  273u     sock       0,9      0t0 109485364 protocol: TCP
duplicacy 24909 root  274u     sock       0,9      0t0 109485375 protocol: TCP
duplicacy 24909 root  275u     sock       0,9      0t0 109486279 protocol: TCP
duplicacy 24909 root  276u     sock       0,9      0t0 109485392 protocol: TCP
duplicacy 24909 root  277u     sock       0,9      0t0 109486299 protocol: TCP
duplicacy 24909 root  278u     sock       0,9      0t0 109486303 protocol: TCP
duplicacy 24909 root  279u     sock       0,9      0t0 109485419 protocol: TCP
duplicacy 24909 root  280u     sock       0,9      0t0 109485502 protocol: TCP
duplicacy 24909 root  281u     sock       0,9      0t0 109485514 protocol: TCP
duplicacy 24909 root  282u     sock       0,9      0t0 109485529 protocol: TCP
duplicacy 24909 root  283u     sock       0,9      0t0 109485537 protocol: TCP
duplicacy 24909 root  284u     sock       0,9      0t0 109485550 protocol: TCP
duplicacy 24909 root  285u     sock       0,9      0t0 109485560 protocol: TCP
duplicacy 24909 root  286u     sock       0,9      0t0 109485602 protocol: TCP
duplicacy 24909 root  287u     sock       0,9      0t0 109486500 protocol: TCP
duplicacy 24909 root  288u     sock       0,9      0t0 109486504 protocol: TCP
duplicacy 24909 root  289u     sock       0,9      0t0 109486506 protocol: TCP
duplicacy 24909 root  290u     sock       0,9      0t0 109486512 protocol: TCP
duplicacy 24909 root  291u     sock       0,9      0t0 109486523 protocol: TCP
duplicacy 24909 root  292u     sock       0,9      0t0 109486529 protocol: TCP
duplicacy 24909 root  293u     sock       0,9      0t0 109486537 protocol: TCP
duplicacy 24909 root  294u     sock       0,9      0t0 109486567 protocol: TCP
duplicacy 24909 root  295u     sock       0,9      0t0 109486573 protocol: TCP
duplicacy 24909 root  296u     sock       0,9      0t0 109486581 protocol: TCP
duplicacy 24909 root  297u     sock       0,9      0t0 109485720 protocol: TCP
duplicacy 24909 root  298u     sock       0,9      0t0 109486605 protocol: TCP
duplicacy 24909 root  299u     sock       0,9      0t0 109485753 protocol: TCP
duplicacy 24909 root  300u     sock       0,9      0t0 109486613 protocol: TCP
duplicacy 24909 root  301u     sock       0,9      0t0 109486634 protocol: TCP
duplicacy 24909 root  302u     IPv4 109486949      0t0       TCP server.lan:35730->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  303u     IPv4 109486963      0t0       TCP server.lan:35760->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  304u     IPv4 109486972      0t0       TCP server.lan:35784->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  305u     IPv4 109487021      0t0       TCP server.lan:35824->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  306u     sock       0,9      0t0 109487028 protocol: TCP
duplicacy 24909 root  307u     sock       0,9      0t0 109489018 protocol: TCP
duplicacy 24909 root  308u     sock       0,9      0t0 109489036 protocol: TCP
duplicacy 24909 root  309u     sock       0,9      0t0 109489038 protocol: TCP
duplicacy 24909 root  310u     sock       0,9      0t0 109487083 protocol: TCP
duplicacy 24909 root  311u     IPv4 109489076      0t0       TCP server.lan:36050->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  312u     IPv4 109490196      0t0       TCP server.lan:36284->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  313u     IPv4 109492886      0t0       TCP server.lan:37898->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  314u     IPv4 109494897      0t0       TCP server.lan:38024->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  315u     IPv4 109492968      0t0       TCP server.lan:38064->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  316u     IPv4 109494986      0t0       TCP server.lan:38366->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  317u     IPv4 109494994      0t0       TCP server.lan:38402->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  318u     IPv4 109493179      0t0       TCP server.lan:38432->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  319u     IPv4 109493184      0t0       TCP server.lan:38450->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  320u     IPv4 109493202      0t0       TCP server.lan:38484->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  321u     IPv4 109495451      0t0       TCP server.lan:38798->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  322u     IPv4 109495485      0t0       TCP server.lan:38864->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  323u     IPv4 109495505      0t0       TCP server.lan:38894->api13.pcloud.com:https (CLOSE_WAIT)
duplicacy 24909 root  324u     IPv4 109498238      0t0       TCP server.lan:39210->api13.pcloud.com:https (ESTABLISHED)
duplicacy 24909 root  325u     IPv4 109498241      0t0       TCP server.lan:39220->api13.pcloud.com:https (ESTABLISHED)

Just to make sure that I didn’t do something wrong: I downloaded the new binary into .duplicacy-web/bin/ and made it executable with chmod +x, moved the existing binary duplicacy_linux_x64_2.6.1 out of there and renamed the new binary to that name (it didn’t work when I left the name at duplicacy_linux_x64_2.6.11 and I couldn’t find the symlink that I suppose is pointing at the other name so I just renamed the file). When I started by check comman and looked for the pid I got this:

$ ps aux | grep duplicacy
root       959  0.0  0.2 196800 16984 ?        Ssl  Aug25   3:45 /usr/bin/duplicacy-web
root     24909  4.1  0.7 127144 57220 ?        Sl   14:36   0:03 /.duplicacy-web/bin/duplicacy_linux_x64_2.6.1 -log -v check -storage pcloud -a -tabular
root     26258  0.0  0.0   6204   824 pts/2    S+   14:37   0:00 grep duplicacy

So it looks like it was indeed using the new (renamed) binary.

gchen · 6 September 2020 02:54

I found a place where a call to io.Copy(ioutil.Discard, readCloser) should be added but missed by the PR:

github.com

gilbertchen/duplicacy/blob/670cbcd776875f140e58ea82e5f3d6361bb701df/src/duplicacy_webdavstorage.go#L230


			propfind += fmt.Sprintf("<%s/>", p)
		}
		propfind += "</prop>"

		body := fmt.Sprintf(`<?xml version="1.0" encoding="utf-8" ?><propfind xmlns="DAV:">%s</propfind>`, propfind)

		readCloser, _, err := storage.sendRequest("PROPFIND", uri, depth, []byte(body))
		if err != nil {
			return nil, err
		}
		defer readCloser.Close()

		object := WebDAVMultiStatus{}
		err = xml.NewDecoder(readCloser).Decode(&object)
		if err != nil {
			if strings.Contains(err.Error(), "unexpected EOF") && tries < maxTries {
				LOG_WARN("WEBDAV_RETRY", "Retrying on %v", err)
				continue
			}
			return nil, err
		}

So I added that call and made another binary: https://acrosync.com/duplicacy/duplicacy_linux_x64_2.6.12

You can download this binary to /.duplicacy-web/bin/ and then restart the web GUI. It should automatically pick up this version (because it always looks for the highest version in that directory).

Christoph · 6 September 2020 10:00

Ah, so that’s how it works. Good to know. But now it also downloaded 2.6.2 and is using that. Does that also include the changes?

Christoph · 10 September 2020 17:19

@gchen 2.6.2 still fails on “too many open files”

gchen · 11 September 2020 02:36

Did you actually mean 2.6.12? 2.6.2 is the latest version on github but the one I built for you is 2.6.12.

Christoph · 11 September 2020 08:01

You said

so I assumed (hoped) the the fix is also included in 2.6.2. Anyway, when I rename 2.6.12 so that it has the highest number, it fails like this:

2020-09-10 20:21:26.817 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/172' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/172: EOF)
2020-09-10 20:21:56.204 TRACE WEBDAV_RETRY URL request 'MKCOL snapshots/NAS' returned an error (Mkcol https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS: EOF)
2020-09-10 20:22:39.463 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/254' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/254: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: no such host)
2020-09-10 20:22:40.290 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/254' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/254: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: no such host)
2020-09-10 20:22:42.086 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/254' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/254: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: no such host)
2020-09-10 20:22:45.153 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/254' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/254: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: no such host)
2020-09-10 20:22:49.319 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/254' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/254: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: no such host)
2020-09-10 20:23:02.950 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/254' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/254: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: no such host)
2020-09-10 20:23:28.806 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/254' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/254: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: no such host)
2020-09-10 20:24:12.144 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/254' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/254: dial tcp: lookup webdav.pcloud.com on 1.1.1.1:53: no such host)
2020-09-10 20:26:00.704 ERROR SNAPSHOT_INFO Failed to get the information on the snapshot NAS at revision 254: Maximum backoff reached
Failed to get the information on the snapshot NAS at revision 254: Maximum backoff reached

I’m not sure what is going on but my hunch is that the error messages are inaccurate. I don’t belive that 1.1.1.1. actually said no such host. That would be very strange. What seems more likely is that this is still somehow related to the too many open files error but for some reason it is not showing in the log. Either the too many open files are causing duplicacy to send an invalid host name to the DNS or it is sending the correct host-name but then failing to understand the DNS response. Or wait: does no such host refer to 1.1.1.1? In that case the “too many open files” might somehow be preventing duplicacy from accessing the DNS server.

In any case, here is what my hunch is based on:

The log of duplicacy’s open files (obtained as described above) has the same pattern with 2.6.12 and 2.6.2 (hundreds of duplicacy 560 root 18u sock 0,9 0t0 154721532 protocol: TCP and hundres of duplicacy 560 root 887u IPv4 154828376 0t0 TCP server.lan:39200->api13.pcloud.com:https (CLOSE_WAIT) in both cases.
When running 2.6.2. it also fails in connection with DNS queries, except that the error message explicitly mentions too many open files. It says:
(I pasted the end of the log in this post).
We already had the same kind of error a couple of months ago (see this post above) but at the time we assumed that this actually was a DNS failure because I used a less popular DNS server then. In retrospect, I’m inclined to believe that even that DNS server was working fine back then.

So it seems to be somewhat random whether “too many open files” exctually shows in the logs or not but the root cause is likely the same.

gchen · 14 September 2020 15:45

I found another place where the response body wasn’t properly closed: Close the response body when 301 is returned in the WebDAV backend · gilbertchen/duplicacy@97bae5f · GitHub

However, I’m not sure this bug is the culprit in your case. This bug is triggered only when Duplicacy attempts to create directories, and only a backup job will create new directories. Plus, there are at most 256 subdirectories to create (with the default chunk nesting level of 1), so at most 256 file handles will be leaked which is usually less than the default limit on the number of files a process can open.

So, what is the type of jobs that kept failing for you and are you using a nesting level of 2?

Christoph · 14 September 2020 16:45

The job that keeps failing is a check job. backup jobs tend to work fine.

I have not changed anything with regards to nesting so if the default is 1, it is still 1. Looking at my storage, I see that there is only one more level of directories under ../chunks (folders 0a to ff). Each of these folders only contains chunks, no more folders.

@gchen What more can I do to track this down?

gchen · 18 September 2020 23:30

Can you send me a full log?

Christoph · 19 September 2020 17:25

Sent you a PM. Hope you find something interesting.

gchen · 25 September 2020 18:20

I believe this commit should fix the problem: Improvements for the WebDAV backend · gilbertchen/duplicacy@e3e3e97 · GitHub

From the log you sent me it is obvious that somehow pcloud returns EOFs when Duplicacy tries to create snapshot subdirectories, and Duplicacy keeps trying causing too many connections (I don’t think connections are leaking; it is just that too many connections are created in a short period of time).

This latest commit fixes two things. First, those snapshot subdirectories actually already exist in the storage – we can find them when listing the snapshot directory and store them in the cache. This should avoid unnecessary calls to CreateDirectory(). Second, when pcloud returns EOF on CreateDirectory() we’ll assume the directory already exists.

I’ll make a new CLI release over the weekend which will include this commit.

Christoph · 25 September 2020 20:13

Excellent! Sounds like we are getting somewhere!

It wouldn’t have occurred to me that the check command creates directories (or anything, for that matter). Why does it do that?

So the “too many open files” are actually too many connections? Because in Linux everything is a file?