Upload stops after 1 minute

[insajd]

droppy 12.0.1
node 14.5.0
Installed using docker silverwind/droppy:latest
Same behavior in new Edge , Chrome.
Log where error can be seen - any upload is cancelled after ~1 minute of uploading
Can you suggest where should I search for the culprit?

2020-08-17 04:52:47 [INFO] xxx:49374 GET /!/token [200] [1ms],
2020-08-17 04:52:47 [INFO] xxx:56039 WebSocket [connected],
2020-08-17 04:52:56 [INFO] xxx:13395 POST /!/upload?vId=0&to=/&rename=0 [200] [6ms] Upload started,
2020-08-17 04:53:56 [INFO] xxx:13395 POST /!/upload?vId=0&to=/&rename=0 [200] [60057ms] Upload cancelled

Config file

{
  "listeners": [
    {
      "host": [
        "0.0.0.0",
        "::"
      ],
      "port": 8989,
      "protocol": "http"
    }
  ],
  "public": false,
  "timestamps": true,
  "linkLength": 5,
  "linkExtensions": false,
  "logLevel": 2,
  "maxFileSize": 0,
  "updateInterval": 1000,
  "pollingInterval": 0,
  "keepAlive": 20000,
  "allowFrame": false,
  "readOnly": false,
  "ignorePatterns": [],
  "watch": true,
  "headers": {}
}

[silverwind]

Is there a reverse proxy or are you connecting directly? Reverse proxies generally have very low request timeouts that need to be adjusted.

[Cubox]

Same issue with nginx
It's nginx's fault for sure

[insajd]

I used domain without reverse proxy, but just tried directly using ip address, and still same issue.
Public IP address:8989 -> forwarded using Mikrotik router -> local IP address. Local IP address is one of the Proxmox VMs. The machine got Debian with docker installed. On docker I'm running Droppy.
Starting to think it might be something to do with Proxmox..

[silverwind]

60s is the default timeout of nginx. See the wiki. You want to at least set these:

proxy_connect_timeout 7200;
proxy_read_timeout 7200;
proxy_send_timeout 7200;
client_max_body_size 0;

I usually set all these timeouts:

client_body_timeout 7200;
client_header_timeout 7200;
proxy_connect_timeout 7200;
proxy_read_timeout 7200;
proxy_send_timeout 7200;
send_timeout 7200;

[insajd]

I'm not using nginx.

I tried different approach - Ubuntu VM on digitalocean, again installed droppy using docker, and same issue in there. 60 seconds pass - it breaks.
Then I installed droppy using npm on my local machine which runs docker - then no issue is present, I uploaded file without any problems.

So far conclusion is that when using docker image, I can't upload anything for longer than 60 seconds.

[insajd]

Additionally what I noticed - on debian node version 10.21.0 is used(I installed whatever installed with apt install npm), in docker 14.5.0 is used.

[Cubox]

60s is the default timeout of nginx. See the wiki. You want to at least set these:

proxy_connect_timeout 7200;
proxy_read_timeout 7200;
proxy_send_timeout 7200;
client_max_body_size 0;

I usually set all these timeouts:

client_body_timeout 7200;
client_header_timeout 7200;
proxy_connect_timeout 7200;
proxy_read_timeout 7200;
proxy_send_timeout 7200;
send_timeout 7200;

I tried with all of those. I already had the top ones, but even with client_body_timeout and send_timeout added, same issue.
I'll try to use droppy without the reverse proxy and see if I have the same issue.
My guess is this change: Change: now nginx starts closing keepalive connections before all free worker connections are exhausted, and logs a warning about this to the error log. from https://nginx.org/en/CHANGES

[Cubox]

I just updated droppy to 12.0.1, and tried directly (connecting to the port and not using reverse proxy) and I get the same issue.

I have an Upload cancelled after 60004ms

[Cubox]

Droppy config: 2020-08-18 18:35:57 [INFO] Configuration: { listeners: [ { host: [ '0.0.0.0' ], port: 8989, protocol: 'http' } ], public: false, timestamps: true, linkLength: 5, linkExtensions: true, logLevel: 2, maxFileSize: 0, updateInterval: 1000, pollingInterval: 0, keepAlive: 20000, allowFrame: false, readOnly: false, ignorePatterns: [ '.*' ], watch: true, headers: {}}

2020-08-18 18:36:25 [INFO] 1:52317 POST /!/upload?vId=0&to=/&rename=0 [200] [2ms] Upload started
2020-08-18 18:37:25 [INFO] 1:52317 POST /!/upload?vId=0&to=/&rename=0 [200] [60004ms] Upload cancelled

[insajd]

Regarding docker issue found this, might be the reason?
Docker uses IP Virtual Server and IPVS maintains its own connection table. The default timeout for CLOSE_WAIT connections in IPVS table is 60 seconds. Hence when the server sends something after 60 seconds, the IPVS connection is no longer available and the packet looks invalid for a new TCP session and gets RST. On the client side, the connection remains forever in FIN_WAIT2 state because the app still has the socket open; kernel's fin_wait timer kicks in only for orphaned TCP sockets.
https://stackoverflow.com/questions/43311004/docker-services-stops-communicating-after-some-time

[Cubox]

@insajd Since I'm having this issue, and I don't use docker, I don't think it's that.
Can you try with an instance not using docker? I'll bet you will still have this issue.

[silverwind]

Try with 12.1.0. I was able to reproduce behind nginx which logged

upstream prematurely closed connection while reading response header from upstream

which does point to the fault being node. Interestingly, it dit not show on macOS, only Linux.

12.1.0 adds a new uploadTimeout option that defaults to 7 days.

[Cubox]

Updated to 12.1.0 and I have the same behaviour, even in direct (no nginx around).
After 60s it reset the upload and tried again (issued another POST) and after the second one failed, gave up.

[silverwind]

There's one more timeout that I can think of but it doesn't really make sense that it would be it because uploads should have their headers sent when that timeout hits.

Do you see any errors in the log when it happens or is it just a "Upload Cancelled"?

[insajd]

Tried a lot of test cases. Somehow now it works for me in most cases with an exception of reverse proxy:

Running natively without docker on : Linux debian 4.19.0-9-amd64 #1 SMP Debian 4.19.118-2+deb10u1 (2020-06-07) x86_64 GNU/Linux

1. droppy 12.0.1 running on node 10.21.0
   2020-08-19 07:11:13 [INFO] 192.168.192.254:9762 POST /!/upload?vId=0&to=/&rename=0 [200] [2ms] Upload started
   2020-08-19 07:20:37 [INFO] 192.168.192.254:9762 POST /!/upload?vId=0&to=/&rename=0 [200] [564571ms] Received 1 files
   -upload works

2. Updated nodejs to v12.18.3
   droppy 12.0.1 running on node 12.18.3
   2020-08-19 07:26:57 [INFO] 192.168.192.254:10995 POST /!/upload?vId=0&to=/&rename=0 [200] [4ms] Upload started
   2020-08-19 07:30:16 [INFO] 192.168.192.254:10995 POST /!/upload?vId=0&to=/&rename=0 [200] [199515ms] Received 1 files
   -upload works

3. Updated droppy
   droppy 12.1.0 running on node 12.18.3
   2020-08-19 07:39:10 [INFO] 192.168.192.254:11839 POST /!/upload?vId=0&to=/&rename=0 [200] [2ms] Upload started
   2020-08-19 07:42:00 [INFO] 192.168.192.254:11839 POST /!/upload?vId=0&to=/&rename=0 [200] [170091ms] Received 1 files
   -upload works

4. Updated to latest node
   droppy 12.1.0 running on node 14.8.0
   2020-08-19 07:45:54 [INFO] 192.168.192.254:12312 POST /!/upload?vId=0&to=/&rename=0 [200] [2ms] Upload started
   2020-08-19 07:48:25 [INFO] 192.168.192.254:12312 POST /!/upload?vId=0&to=/&rename=0 [200] [150425ms] Received 1 files
   -upload works

Running in docker

1. droppy 12.1.0 running on node 14.8.0
   Built it using

git clone https://github.com/silverwind/droppy
cd droppy
npm install
./droppy build . -t "test:droppy"

2020-08-19 05:42:51 [INFO] 192.168.192.254:9855 POST /!/upload?vId=0&to=/&rename=0 [200] [5ms] Upload started
2020-08-19 05:45:33 [INFO] 192.168.192.254:9855 POST /!/upload?vId=0&to=/&rename=0 [200] [161817ms] Received 1 files,
-upload works

2. Using silverwind/droppy:latest image
   droppy 12.1.0 running on node 14.8.0
   2020-08-19 05:47:02 [INFO] 192.168.192.254:10135 POST /!/upload?vId=0&to=/&rename=0 [200] [2ms] Upload started,
   2020-08-19 05:49:52 [INFO] 192.168.192.254:10135 POST /!/upload?vId=0&to=/&rename=0 [200] [170372ms] Received 1 files
   -upload works

Added Nginx reverse proxy

droppy 12.1.0 running on node 14.8.0
Upload doesn't get cancelled, but it hangs on 100% without finishing file
-upload doesn't work.

Public IP:port

droppy 12.1.0 running on node 14.8.0
2020-08-19 06:09:41 [INFO] 87.246.xxx.xxx:8189 POST /!/upload?vId=0&to=/&rename=0 [200] [1ms] Upload started,
2020-08-19 06:13:08 [INFO] 87.246.xxx.xxx:8189 POST /!/upload?vId=0&to=/&rename=0 [200] [206532ms] Received 1 files

-upload works

[Cubox]

There's one more timeout that I can think of but it doesn't really make sense that it would be it because uploads should have their headers sent when that timeout hits.

Do you see any errors in the log when it happens or is it just a "Upload Cancelled"?

Just Upload Cancelled

[Cubox]

I'm running FreeBSD 12.1-STABLE, with node v14.6.0 and npm 6.14.8