What does this error indicate?

1. Caddy version (caddy version):

2.4.5

2. How I run Caddy:

a. System environment:

Windows 10 x64 v21H1

b. Command:

caddy_windows_amd64.exe run

c. Service/unit/compose file:

Paste full file contents here.
Make sure backticks stay on their own lines,
and the post looks nice in the preview pane.

d. My complete Caddyfile or JSON config:

{
	log caddy-log {
		output file caddy.log {
			roll_size 10MiB
			roll_keep 5
			roll_keep_for 2160h
		}
	}

	default_sni thedomain.com
	#debug
}
http:// {
	respond "why you here?"
}
web.thedomain.com:8443 {
	reverse_proxy :81
	tls {
		protocols tls1.2
	}
	header / Strict-Transport-Security "max-age=63072000"
}
media.thedomain.com:8443 {
	reverse_proxy :8096
	tls {
		protocols tls1.2
	}
	header / Strict-Transport-Security "max-age=63072000"
}
# local filebrowser test
:82 {
	reverse_proxy :8080
}
# local HFS test
:83 {
	reverse_proxy :81
}

3. The problem I’m having:

This is an intermittent error. From the Internet, I login to my file server app via web browser, browse to subfolder “UL”, then try to upload a file. The upload appears to start but no data is transferred (like it is stuck), no errors shown in the app. Caddy issues an error.

4. Error messages and/or full log output:

http.log.error readfrom tcp 127.0.0.1:53845->127.0.0.1:81: client disconnected {“request”: {“remote_addr”: “139.xyz.xyz.45:10400”, “proto”: “HTTP/2.0”, “method”: “POST”, “host”: “web.thedomain.com”, “uri”: “/UL/”, “headers”: {“Accept-Encoding”: [“gzip, deflate, br”], “Origin”: [“https://web.thedomain.com”], “Sec-Fetch-Mode”: [“navigate”], “Sec-Fetch-User”: ["?1"], “User-Agent”: [“Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:94.0) Gecko/20100101 Firefox/94.0”], “Accept-Language”: [“en-US,en;q=0.5”], “Referer”: [“https://web.thedomain.com/UL/”], “Upgrade-Insecure-Requests”: [“1”], “Sec-Fetch-Dest”: [“document”], “Sec-Fetch-Site”: [“same-origin”], “Accept”: [“text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,/;q=0.8”], “Content-Type”: [“multipart/form-data; boundary=---------------------------352751372540989882361939689133”], “Authorization”: [“Basic dWw6dGlnZXIhdXBsb2FkMDAuLg==”], “Cookie”: [“HFS_SID_=0.170372180873528”], “Te”: [“trailers”], “Content-Length”: [“5457802169”], “Dnt”: [“1”]}, “tls”: {“resumed”: false, “version”: 772, “cipher_suite”: 4865, “proto”: “h2”, “proto_mutual”: true, “server_name”: “web.thedomain.com”}}, “duration”: 20.3282403, “status”: 502, “err_id”: “frd8dqdzw”, “err_trace”: “reverseproxy.statusError (reverseproxy.go:858)”}

5. What I already tried:

Nothing.

6. Links to relevant resources:

(edited, re-read your statement on intermittent)

What application is listening on port 81? Have you tested directly connecting locally to that port (81) on the host and attempted the upload taking caddy out of it? Does it ever fail in that type of testing scenario?

Also is there a way to test with less specific settings around SNI and specific TLS version and transport security to possibly isolate where the breakage is taking place? Or is the underlying application listening on port 81 requiring it? It might help isolate where the breakage is taking place.

For example:

web.thedomain.com:8443 {
	reverse_proxy :81
}
1 Like

Ah, sorry that deleted post I made was pointing at current main source code around line 858 rather than the 2.4.5 release which would be this instead:

Which really is not helpful, the specific message of “frd8dqdzw” is possibly emitting from go? So the error message is all we have to work from…

That’s just a unique random string that Caddy assigns to errors so you can identify instances of errors in your logs.

Formatted the error message to make parsing easier too…

http.log.error readfrom tcp 127.0.0.1: 53845->127.0.0.1: 81: client disconnected 
    {“request”: 
        {“remote_addr”: “139.xyz.xyz.45: 10400”, 
            “proto”: “HTTP/2.0”, “method”: “POST”, “host”: “web.thedomain.com”, “uri”: “/UL/”, “headers”: 
            {“Accept-Encoding”: [“gzip, deflate, br”], 
                “Origin”: [“https: //web.thedomain.com”], 
                “Sec-Fetch-Mode”: [“navigate”], 
                “Sec-Fetch-User”: ["?1"], 
                “User-Agent”: [“Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:94.0) Gecko/20100101 Firefox/94.0”], 
                “Accept-Language”: [“en-US,en;q=0.5”], 
                “Referer”: [“https://web.thedomain.com/UL/”], 
                “Upgrade-Insecure-Requests”: [“1”], 
                “Sec-Fetch-Dest”: [“document”], 
                “Sec-Fetch-Site”: [“same-origin”], 
                “Accept”: [“text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,/;q=0.8”], 
                “Content-Type”: [“multipart/form-data; boundary=---------------------------352751372540989882361939689133”], 
                “Authorization”: [“Basic dWw6dGlnZXIhdXBsb2FkMDAuLg==”], 
                “Cookie”: [“HFS_SID_=0.170372180873528”], 
                “Te”: [“trailers”], 
                “Content-Length”: [“5457802169”], 
                “Dnt”: [“1”]
            }, 
        “tls”: 
            {“resumed”: false, “version”: 772, “cipher_suite”: 4865, “proto”: “h2”, “proto_mutual”: true, “server_name”: “web.thedomain.com”}
        }, 
    “duration”: 20.3282403, “status”: 502, “err_id”: “frd8dqdzw”, “err_trace”: “reverseproxy.statusError (reverseproxy.go:858)”
    }
1 Like

Question to @JustinWebDev - so this error you are showing, the file size being uploaded is > 5GB in size (5.457802169 to be exact).

You were stating that this happens intermittently; is file size related in any way to when it happens vs does not happen? Or does this happen for both large and small file sizes?

1 Like

It looks like you are using HFS (HFS ~ HTTP File Server) here, is that what is listening on port 81? If so could you expand the logging options on it ( HFS: Log menu - rejetto wiki ) to include “connections, disconnections, replies and bytes received” and have it write to a file that we can attempt to correlate to a failure event with caddy?

1 Like

I’ve seen the same thing with filebrowser, so I’m thinking it is not because of the file server app. I’ve attempted only large files (.5GB and up).
I’ll try with barebones config and with extra logging and v2.4.6.

Did a test per your suggestions. Here is the log from HFS.
You can see the error at 11/10/2021 11:42:53
Then you see two attempts to upload.
The first upload aborted after ~5MB, the second attempt was smooth for the ~3GB.
I don’t know why I’m getting a mixture of 127.0.0.1 and the remote IP.

11/10/2021 11:42:12 AM 127.0.0.1 57155 Connected
11/10/2021 11:42:12 AM 139.xyz.xyz.45 57155 Requested GET /
11/10/2021 11:42:12 AM 139.xyz.xyz.45 57155 Request dump

GET / HTTP/1.1
Host: web.thedomain.com
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.69 Safari/537.36 Edg/95.0.1020.44
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3;q=0.9
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
Sec-Ch-Ua: “Microsoft Edge”;v=“95”, “Chromium”;v=“95”, “;Not A Brand”;v=“99”
Sec-Ch-Ua-Mobile: ?0
Sec-Ch-Ua-Platform: “Windows”
Sec-Fetch-Dest: document
Sec-Fetch-Mode: navigate
Sec-Fetch-Site: none
Sec-Fetch-User: ?1
Upgrade-Insecure-Requests: 1
X-Forwarded-For: 139.xyz.xyz.45
X-Forwarded-Proto: https
11/10/2021 11:42:12 AM 139.xyz.xyz.45 57155 Not served: 401 - Unauthorized
11/10/2021 11:42:12 AM 139.xyz.xyz.45 57155 Disconnected by server - 1092 bytes sent
11/10/2021 11:42:18 AM 127.0.0.1 57156 Connected
11/10/2021 11:42:18 AM ul 139.xyz.xyz.45 57156 Requested GET /
11/10/2021 11:42:18 AM ul 139.xyz.xyz.45 57156 Request dump
GET / HTTP/1.1
Host: web.thedomain.com
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.69 Safari/537.36 Edg/95.0.1020.44
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3;q=0.9
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
Authorization: Basic dWw6dGlnZXIhdXBsb2FkMDAuLg==
Cache-Control: max-age=0
Cookie: HFS_SID_=0.808680337155238
Sec-Ch-Ua: “Microsoft Edge”;v=“95”, “Chromium”;v=“95”, “;Not A Brand”;v=“99”
Sec-Ch-Ua-Mobile: ?0
Sec-Ch-Ua-Platform: “Windows”
Sec-Fetch-Dest: document
Sec-Fetch-Mode: navigate
Sec-Fetch-Site: none
Sec-Fetch-User: ?1
Upgrade-Insecure-Requests: 1
X-Forwarded-For: 139.xyz.xyz.45
X-Forwarded-Proto: https
11/10/2021 11:42:18 AM ul 139.xyz.xyz.45 57156 Served 2.0 K
11/10/2021 11:42:20 AM 127.0.0.1 57157 Connected
11/10/2021 11:42:20 AM 127.0.0.1 57158 Connected
11/10/2021 11:42:20 AM 127.0.0.1 57159 Connected
11/10/2021 11:42:20 AM 127.0.0.1 57160 Connected
11/10/2021 11:42:20 AM 127.0.0.1 57161 Connected
11/10/2021 11:42:20 AM 127.0.0.1 57162 Connected
11/10/2021 11:42:24 AM ul 139.xyz.xyz.45 57161 Requested GET /UL/
11/10/2021 11:42:24 AM ul 139.xyz.xyz.45 57161 Request dump
GET /UL/ HTTP/1.1
Host: web.thedomain.com
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.69 Safari/537.36 Edg/95.0.1020.44
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3;q=0.9
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
Authorization: Basic dWw6dGlnZXIhdXBsb2FkMDAuLg==
Cookie: HFS_SID_=0.808680337155238
Referer: https://web.thedomain.com/
Sec-Ch-Ua: “Microsoft Edge”;v=“95”, “Chromium”;v=“95”, “;Not A Brand”;v=“99”
Sec-Ch-Ua-Mobile: ?0
Sec-Ch-Ua-Platform: “Windows”
Sec-Fetch-Dest: document
Sec-Fetch-Mode: navigate
Sec-Fetch-Site: same-origin
Sec-Fetch-User: ?1
Upgrade-Insecure-Requests: 1
X-Forwarded-For: 139.xyz.xyz.45
X-Forwarded-Proto: https
11/10/2021 11:42:24 AM ul 139.xyz.xyz.45 57161 Served 2.2 K
11/10/2021 11:42:24 AM 127.0.0.1 57163 Connected
11/10/2021 11:42:24 AM 127.0.0.1 57164 Connected
11/10/2021 11:42:24 AM 127.0.0.1 57165 Connected
11/10/2021 11:42:53 AM ul 139.xyz.xyz.45 57165 Uploading TheFileToUpload.exe
11/10/2021 11:43:15 AM ul 139.xyz.xyz.45 57165 Disconnected - 952 bytes sent
11/10/2021 11:43:15 AM ul 139.xyz.xyz.45 57163 Uploading TheFileToUpload.exe
11/10/2021 11:43:25 AM ul 139.xyz.xyz.45 57156 Disconnected by server: inactivity - 4047 bytes sent
11/10/2021 11:43:25 AM ul 139.xyz.xyz.45 57158 Disconnected by server: inactivity - 937 bytes sent
11/10/2021 11:43:25 AM ul 139.xyz.xyz.45 57160 Disconnected by server: inactivity - 7843 bytes sent
11/10/2021 11:43:25 AM ul 139.xyz.xyz.45 57162 Disconnected by server: inactivity - 336 bytes sent
11/10/2021 11:43:26 AM ul 139.xyz.xyz.45 57157 Disconnected by server: inactivity - 9600 bytes sent
11/10/2021 11:43:26 AM ul 139.xyz.xyz.45 57161 Disconnected by server: inactivity - 4684 bytes sent
11/10/2021 11:43:26 AM ul 139.xyz.xyz.45 57159 Disconnected by server: inactivity - 953 bytes sent
11/10/2021 11:47:52 AM ul 139.xyz.xyz.45 57163 Fully uploaded TheFileToUpload.exe - 3.3 G @ 12.4 MB/s
11/10/2021 11:47:52 AM ul 139.xyz.xyz.45 57163 Requested POST /UL/
11/10/2021 11:47:52 AM ul 139.xyz.xyz.45 57163 Request dump
POST /UL/ HTTP/1.1
Host: web.thedomain.com
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.69 Safari/537.36 Edg/95.0.1020.44
Content-Length: 3595133559
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3;q=0.9
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
Authorization: Basic dWw6dGlnZXIhdXBsb2FkMDAuLg==
Cache-Control: max-age=0
Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryn74EBtEG32Wq2typ
Cookie: HFS_SID_=0.808680337155238
Origin: https://web.thedomain.com
Referer: https://web.thedomain.com/UL/
Sec-Ch-Ua: “Microsoft Edge”;v=“95”, “Chromium”;v=“95”, “;Not A Brand”;v=“99”
Sec-Ch-Ua-Mobile: ?0
Sec-Ch-Ua-Platform: “Windows”
Sec-Fetch-Dest: document
Sec-Fetch-Mode: navigate
Sec-Fetch-Site: same-origin
Sec-Fetch-User: ?1
Upgrade-Insecure-Requests: 1
X-Forwarded-For: 139.xyz.xyz.45
X-Forwarded-Proto: https
11/10/2021 11:47:52 AM ul 139.xyz.xyz.45 57163 Served 563
11/10/2021 11:48:00 AM ul 139.xyz.xyz.45 57164 Requested GET /UL/
11/10/2021 11:48:00 AM ul 139.xyz.xyz.45 57164 Request dump
GET /UL/ HTTP/1.1
Host: web.thedomain.com
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.69 Safari/537.36 Edg/95.0.1020.44
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3;q=0.9
Accept-Encoding: gzip, deflate, br
Accept-Language: en-US,en;q=0.9
Authorization: Basic dWw6dGlnZXIhdXBsb2FkMDAuLg==
Cookie: HFS_SID_=0.808680337155238
Referer: https://web.thedomain.com/UL/
Sec-Ch-Ua: “Microsoft Edge”;v=“95”, “Chromium”;v=“95”, “;Not A Brand”;v=“99”
Sec-Ch-Ua-Mobile: ?0
Sec-Ch-Ua-Platform: “Windows”
Sec-Fetch-Dest: document
Sec-Fetch-Mode: navigate
Sec-Fetch-Site: same-origin
Sec-Fetch-User: ?1
Upgrade-Insecure-Requests: 1
X-Forwarded-For: 139.xyz.xyz.45
X-Forwarded-Proto: https
11/10/2021 11:48:00 AM ul 139.xyz.xyz.45 57164 Served 2.1 K
11/10/2021 11:48:00 AM 127.0.0.1 57167 Connected
11/10/2021 11:48:00 AM 127.0.0.1 57168 Connected
11/10/2021 11:48:00 AM 127.0.0.1 57169 Connected
11/10/2021 11:48:00 AM 127.0.0.1 57170 Connected
11/10/2021 11:48:00 AM 127.0.0.1 57171 Connected
11/10/2021 11:48:24 AM ul 139.xyz.xyz.45 57163 Disconnected by server - 9982 bytes sent
11/10/2021 11:48:24 AM ul 139.xyz.xyz.45 57167 Disconnected by server - 756 bytes sent
11/10/2021 11:48:24 AM ul 139.xyz.xyz.45 57169 Disconnected by server - 646 bytes sent
11/10/2021 11:48:24 AM ul 139.xyz.xyz.45 57171 Disconnected by server - 694 bytes sent
11/10/2021 11:48:24 AM ul 139.xyz.xyz.45 57164 Disconnected by server - 37396 bytes sent
11/10/2021 11:48:24 AM ul 139.xyz.xyz.45 57170 Disconnected by server - 336 bytes sent
11/10/2021 11:48:24 AM ul 139.xyz.xyz.45 57168 Disconnected by server - 605 bytes sent

I think this is because the connection actually comes from Caddy which is running on the same machine (i.e. 127.0.0.1), but since Caddy sends the X-Forwarded-For header with the real IP address of the client, HFS knows after parsing the request (which is after the initial connection) that the client’s real IP is 139.xyz.xyz.45 and prints that out for subsequent messages.

1 Like

I’m assuming this test was over the reduced caddy rule set as well that we talked about?

web.thedomain.com:8443 {
	reverse_proxy :81
}

Can we get the caddy logs for this same window of time so we see what was happening there around the time of failure you identified.

Also, can you qualify the time range of the failed upload that failed at the 5mb level. I see a 401 authentication error and I’m not sure if that is just noise or during the window of the failed upload attempt?

1 Like

Yes, with the simplified Caddy file. I think that 401 is the when you first connect and the server sees you are not authenticated then responds with login dialog.

Caddy error at same time (only error emitted):
2021/11/10 17:43:15.226 error http.log.error readfrom tcp 127.0.0.1:57165->127.0.0.1:81: client disconnected {“request”: {“remote_addr”: “139.xyz.xyz.45:56128”, “proto”: “HTTP/2.0”, “method”: “POST”, “host”: “web.thedomain.com”, “uri”: “/UL/”, “headers”: {“Cookie”: [“HFS_SID_=0.808680337155238”], “Authorization”: [“Basic dWw6dGlnZXIhdXBsb2FkMDAuLg==”], “Sec-Ch-Ua”: ["“Microsoft Edge”;v=“95”, “Chromium”;v=“95”, “;Not A Brand”;v=“99"”], “Sec-Ch-Ua-Platform”: ["“Windows”"], “Accept”: [“text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3;q=0.9”], “Sec-Fetch-User”: ["?1"], “Accept-Encoding”: [“gzip, deflate, br”], “Accept-Language”: [“en-US,en;q=0.9”], “Cache-Control”: [“max-age=0”], “Sec-Ch-Ua-Mobile”: ["?0"], “Content-Type”: [“multipart/form-data; boundary=----WebKitFormBoundaryn74EBtEG32Wq2typ”], “User-Agent”: [“Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.69 Safari/537.36 Edg/95.0.1020.44”], “Sec-Fetch-Site”: [“same-origin”], “Sec-Fetch-Mode”: [“navigate”], “Content-Length”: [“3595133559”], “Upgrade-Insecure-Requests”: [“1”], “Origin”: [“https://web.thedomain.com”], “Referer”: [“https://web.thedomain.com/UL/”], “Sec-Fetch-Dest”: [“document”]}, “tls”: {“resumed”: false, “version”: 772, “cipher_suite”: 4865, “proto”: “h2”, “proto_mutual”: true, “server_name”: “web.thedomain.com”}}, “duration”: 22.2100242, “status”: 502, “err_id”: “qqcbcm7b4”, “err_trace”: “reverseproxy.statusError (reverseproxy.go:886)”}

So the failing file was almost 3.6 GB in size (just noting)

(for ease of parsing I’m reposting the log) I’m tagging the timestamp with ** ** below as its important to associate what the caddy vs HFS logs were showing for the same window of time.

2021/11/10 **17:43:15.226** error http.log.error readfrom tcp 127.0.0.1:57165->127.0.0.1:81: client disconnected 
{“request”: 
    {“remote_addr”: “139.xyz.xyz.45:56128”, “proto”: “HTTP/2.0”, “method”: “POST”, “host”: “web.thedomain.com”, “uri”: “/UL/”, “headers”:
     {“Cookie”: 
        [“HFS_SID_=0.808680337155238”],
        “Authorization”: [“Basic dWw6dGlnZXIhdXBsb2FkMDAuLg==”], 
        “Sec-Ch-Ua”: ["“Microsoft Edge”;v=“95”, “Chromium”;v=“95”, “;Not A Brand”;v=“99"”], 
        “Sec-Ch-Ua-Platform”: ["“Windows”"], 
        “Accept”: [“text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3;q=0.9”], 
        “Sec-Fetch-User”: ["?1"], “Accept-Encoding”: [“gzip, deflate, br”], “Accept-Language”: [“en-US,en;q=0.9”], “Cache-Control”: [“max-age=0”], 
        “Sec-Ch-Ua-Mobile”: ["?0"], 
        “Content-Type”: [“multipart/form-data; boundary=----WebKitFormBoundaryn74EBtEG32Wq2typ”], 
        “User-Agent”: [“Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.69 Safari/537.36 Edg/95.0.1020.44”], 
        “Sec-Fetch-Site”: [“same-origin”], 
        “Sec-Fetch-Mode”: [“navigate”], 
        “Content-Length”: [“3595133559”], 
        “Upgrade-Insecure-Requests”: [“1”], 
        “Origin”: [“https://web.thedomain.com”], 
        “Referer”: [“https://web.thedomain.com/UL/”], 
        “Sec-Fetch-Dest”: [“document”]}, 
        “tls”: {“resumed”: false, “version”: 772, “cipher_suite”: 4865, “proto”: “h2”, “proto_mutual”: true, “server_name”: “web.thedomain.com”}}, 
        “duration”: 22.2100242, 
        “status”: 502, 
        “err_id”: “qqcbcm7b4”, 
        “err_trace”: “reverseproxy.statusError (reverseproxy.go:886)
    }

Between the caddy server and the target server running HFS is there really a 6 hour difference or am I just looking at one is in a timezone based config on one host and the other host is configured for UTC? Or is this logging from a separate test? I’m trying to align the two log sets… The 11.42:53 timeframe from your HFS server log seems to end in a successful "Fully uploaded TheFileToUpload.exe - 3.3 G @ 12.4 MB/s

11/10/2021 11:42:53 AM ul 139.xyz.xyz.45 57165 Uploading TheFileToUpload.exe
11/10/2021 11:43:15 AM ul 139.xyz.xyz.45 57165 Disconnected - 952 bytes sent
11/10/2021 11:43:15 AM ul 139.xyz.xyz.45 57163 Uploading TheFileToUpload.exe
11/10/2021 11:43:25 AM ul 139.xyz.xyz.45 57156 Disconnected by server: inactivity - 4047 bytes sent
11/10/2021 11:43:25 AM ul 139.xyz.xyz.45 57158 Disconnected by server: inactivity - 937 bytes sent
11/10/2021 11:43:25 AM ul 139.xyz.xyz.45 57160 Disconnected by server: inactivity - 7843 bytes sent
11/10/2021 11:43:25 AM ul 139.xyz.xyz.45 57162 Disconnected by server: inactivity - 336 bytes sent
11/10/2021 11:43:26 AM ul 139.xyz.xyz.45 57157 Disconnected by server: inactivity - 9600 bytes sent
11/10/2021 11:43:26 AM ul 139.xyz.xyz.45 57161 Disconnected by server: inactivity - 4684 bytes sent
11/10/2021 11:43:26 AM ul 139.xyz.xyz.45 57159 Disconnected by server: inactivity - 953 bytes sent
11/10/2021 11:47:52 AM ul 139.xyz.xyz.45 57163 Fully uploaded TheFileToUpload.exe - 3.3 G @ 12.4 MB/s

I’ll ask around if there is a way to get deeper debugging out of caddy because the fact that the “details” around when this fails and when it does not are not giving us a clear indication of trigger or fault. The 502 status code seems to be pointing away from caddy:

The HyperText Transfer Protocol (HTTP) 502 Bad Gateway server error response code indicates that the server, while acting as a gateway or proxy, received an invalid response from the upstream server .

Other than network failure in the transmission (connections being dropped or reset for some reason) I can not account for why you would see things fail this way.

My next move if I were attempting to isolate what is going on here is drop one level lower an attempt to capture the network traffic at the caddy server with tcpdump to understand if there was actual resets or other types of network layer faults emerging at the TCP conversation level between the “browser” client uploading the file and the caddy server. Is it a true user within a browser that is initiating the upload or is this some form of application that is emulating a browser type to start the transmission of the file to HFS?

Sorry I dont have a more valuable statement to make with regard to what can be causing this. I’ll attempt to bump this to attention (and call out to the rest of the community to share if they have had file transfer through caddy issues in the past).

1 Like

This looks like whatever was attempting to upload the file re-attempted, but the timeframe is almost too tight for user interaction to be initiating the second uploading attempt. It looks like a retry of some sort.

I’d also probably instrument a tcpdump (or wireshark capture) at the HFS server too, but isolating the capture to only the caddyserver’s SRC ip to the HFS servers listener port…

1 Like

Yes, two diff time zones. HFS uses the OS clock; I don’t know how to get Caddy to use the OS clock instead of UTC (which would be nice!).
A true user in a browser, no automation or emulation.

I appreciate your help with this.

Ok so a wireshark capture over the loopback interface is next step, you must install the npcap driver (which wireshark install will offer) to be able to capture loopback traffic on windows (see https://kc.mcafee.com/corporate/index?page=content&id=KB91433 ). You can specifically filter the wireshark capture to focus on the port 81. This will focus on what caddy is doing with the connection back to HFS (it should show both directions of the conversation). If there are wireshark experts following along please correct me here / offer additional filtering to use.

You can set up a capture filter or a display filter in wireshark (capture filter might be better because this is a random event) - the difference is discussed here: Wireshark Q&A

You can modify for the capture filter to be tcp port 81. You will be looking for connection resets on the traffic to/from port 81 which will show up as red/black lines in the connection stream. This gives some insight (google around for other options too “wireshark tutorial follow tcp stream”) but this is a good writeup of basic concepts. https://codeburst.io/basic-tcp-analysis-with-wireshark-b99ed54fa499

It is looking like HFS is unexpectedly disconnecting/resetting connection on caddy here (the 502 status being the indicator up to this point). Using wireshark might help verify where the failure is taking place in the conversation. I would review any content the HFS community has on running with a reverse proxy in front of it. I’ll keep checking around as well.

1 Like

Can you parse this line for me? Who is the client? It looks like the proxy to me. So what would be the significance of the proxy disconnecting?

So the message is emitting from the proxy here on its connection TO the HFS server on port 81, I’m not sure if caddy considers itself the client here or its stating that the upstream client (the browser) disconnected. I’ve asked out of channel for caddy dev team members to help us disassemble this message and its context better.

Looking back at that, it would almost be better to have the full conversation between the browser client and the local conversation between caddy and the hfs server be captured with Wireshark rather than the limited one I indicated, so we can understand where communication breaks down here, but lets get confirmation on the internals around what is going on.

1 Like

So the wireshark “capture filter” would be something like this below with 192.168.1.10 being replaced with your browser IP. It would grab the inbound to caddy and then caddy to HFS. But lets get clarification of the client context before digging there.

(host 192.168.1.10 and dst port 8443) and (host 127.0.01 and dst port 81)
1 Like

Today, while comparing to Stunnel, I could not reproduce at all. I suspect I’ll see it again, but today Caddy did not throw this error or exhibit the problem behavior. I did have to reboot the server over the weekend.

Right, it would be good to at least properly understand the error.