search

omrikiei / ktunnel

A cli that exposes your local resources to kubernetes
GNU General Public License v3.0
925 stars 71 forks source link

Subsequent requests hang for exactly 1 minute #36

Closed mysterybear closed 3 years ago

mysterybear commented 3 years ago

Hey,

I've got it set up and it works, but the request/response round-trip is intermittently very, very slow, or hangs and doesn't complete.

I have no idea what kinds of logs/tests to try to give more meaningful information about this issue, if there are any suggestions I'd be happy to undertake them.

Cheers!

omrikiei commented 3 years ago

hey @mysterybear, could you run the client in verbose mode and share logs

mysterybear commented 3 years ago

Here we go:

INFO[0000] waiting for deployment to be ready           
INFO[0003] Waiting for port forward to finish           
INFO[0003] Forwarding from 127.0.0.1:28688 -> 28688
Forwarding from [::1]:28688 -> 28688 
INFO[2020-12-22 18:35:18.813] starting tcp tunnel from source 3000 to target 3000 
DEBU[2020-12-22 18:35:18.853] attempting to receive from stream            
INFO[2020-12-22 18:35:27.236] new connection                                port=3000 session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:27.236] received 304 bytes from server                session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:27.236] started reading conn                          session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:27.236] wrote 304 bytes to conn                       session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:27.236] attempting to receive from stream            
DEBU[2020-12-22 18:35:27.309] read 245 bytes from conn                      error="<nil>" session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:27.309] wrote 245 bytes to session buf                error="<nil>" session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:27.309] read 245 from buffer out of 245 available     session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:27.309] sending 245 bytes to server                   close=false session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:27.310] sent 245 bytes to server                      close=false session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:32.309] finished reading session                      session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0

DEBU[2020-12-22 18:35:41.278] received 304 bytes from server                session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:41.278] wrote 304 bytes to conn                       session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:35:41.279] attempting to receive from stream            

INFO[2020-12-22 18:36:41.278] closed session                                session=1a4834d0-0b16-4a05-8bdc-46c6aea63cf0
DEBU[2020-12-22 18:36:41.279] attempting to receive from stream            
INFO[2020-12-22 18:36:41.279] new connection                                port=3000 session=b1a2e40f-144b-48b6-861d-ac513c0ede67
DEBU[2020-12-22 18:36:41.279] received 304 bytes from server                session=b1a2e40f-144b-48b6-861d-ac513c0ede67
DEBU[2020-12-22 18:36:41.279] wrote 304 bytes to conn                       session=b1a2e40f-144b-48b6-861d-ac513c0ede67
DEBU[2020-12-22 18:36:41.279] attempting to receive from stream            
DEBU[2020-12-22 18:36:41.279] started reading conn                          session=b1a2e40f-144b-48b6-861d-ac513c0ede67
DEBU[2020-12-22 18:36:41.357] read 245 bytes from conn                      error="<nil>" session=b1a2e40f-144b-48b6-861d-ac513c0ede67
DEBU[2020-12-22 18:36:41.357] wrote 245 bytes to session buf                error="<nil>" session=b1a2e40f-144b-48b6-861d-ac513c0ede67
DEBU[2020-12-22 18:36:41.357] read 245 from buffer out of 245 available     session=b1a2e40f-144b-48b6-861d-ac513c0ede67
DEBU[2020-12-22 18:36:41.357] sending 245 bytes to server                   close=false session=b1a2e40f-144b-48b6-861d-ac513c0ede67
DEBU[2020-12-22 18:36:41.357] sent 245 bytes to server                      close=false session=b1a2e40f-144b-48b6-861d-ac513c0ede67
DEBU[2020-12-22 18:36:46.357] finished reading session                      session=b1a2e40f-144b-48b6-861d-ac513c0ede67

The first request went through very quickly, I hit the return carriage in stdout before the subsequent request and then after the request was made, can see between 18:35:41 and 18:36:41, a 1 minute time for the request to complete

omrikiei commented 3 years ago

are these HTTP requests or is it some kind of a persistent protocol? The way requests are broken down to sessions it seems like it actually took 1 minute to close the previous session (of the first request) and the client was re-using it. Would it also be possible to obtain the server side logs from the ktunnel pod?

mysterybear commented 3 years ago

Thanks for the quick response!

HTTP with TLS, I'm hitting https://rev-prox.[TLD]. I've tried with and without the TLS flag, my latest CLI invocation is like: ktunnel expose -v -n bj-dev -t ktunnel 3000:8080 | tee log 2>&1

Here is the log from the ktunnel server pod:

k logs ktunnel-6dccfbc759-xnnpm -f                                                                                                                                                                                              130 ↵
INFO[2020-12-23 09:19:32.852] Starting to listen on port 28688             
INFO[2020-12-23 09:19:33.792] opening connection                            port=3000 schema=TCP

DEBU[2020-12-23 09:20:40.555] Accepted new connection &{{0xc000250500}}     error="<nil>"
INFO[2020-12-23 09:20:40.555] new connection                                session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.555] read 775 bytes from conn                      error="<nil>"
DEBU[2020-12-23 09:20:40.555] sending 775 bytes to client                   close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.555] sent 775 bytes to client                      close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] received 287 bytes from client                close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] writing 287 bytes to conn                     session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] wrote 287 bytes to conn                       session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.579] received 176 bytes from client                close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.579] writing 176 bytes to conn                     session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.579] wrote 176 bytes to conn                       session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.648] read 694 bytes from conn                      error="<nil>"
DEBU[2020-12-23 09:20:40.648] sending 694 bytes to client                   close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.648] sent 694 bytes to client                      close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.672] received 2219 bytes from client               close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.672] writing 2219 bytes to conn                    session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.672] wrote 2219 bytes to conn                      session=37b969b2-948b-4eb0-ae6d-e843f05728b0

// first request went through fine
// below is after I make a second request

DEBU[2020-12-23 09:21:04.053] read 775 bytes from conn                      error="<nil>"
DEBU[2020-12-23 09:21:04.053] sending 775 bytes to client                   close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:21:04.053] sent 775 bytes to client                      close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0

// hangs here for precisely 1 minute

DEBU[2020-12-23 09:22:04.052] read 0 bytes from conn                        error=EOF
DEBU[2020-12-23 09:22:04.052] sending 0 bytes to client                     close=true session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:22:04.052] sent 0 bytes to client                        close=true session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:22:04.054] Accepted new connection &{{0xc000250580}}     error="<nil>"
INFO[2020-12-23 09:22:04.054] new connection                                session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.054] read 775 bytes from conn                      error="<nil>"
DEBU[2020-12-23 09:22:04.054] sending 775 bytes to client                   close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.054] sent 775 bytes to client                      close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.073] received 287 bytes from client                close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.073] writing 287 bytes to conn                     session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.073] wrote 287 bytes to conn                       session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.073] received 180 bytes from client                close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.073] writing 180 bytes to conn                     session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.073] wrote 180 bytes to conn                       session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.119] read 694 bytes from conn                      error="<nil>"
DEBU[2020-12-23 09:22:04.119] sending 694 bytes to client                   close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.119] sent 694 bytes to client                      close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.166] received 2219 bytes from client               close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.166] writing 2219 bytes to conn                    session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.166] wrote 2219 bytes to conn                      session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:23:04.119] read 0 bytes from conn                        error=EOF
DEBU[2020-12-23 09:23:04.119] sending 0 bytes to client                     close=true session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:23:04.119] sent 0 bytes to client                        close=true session=f605772e-b1a1-4d52-b9ae-203f4220fafa

Same pattern, I added some comments, same pattern, first request fine, made a change to the HTML being served by my local HTTP server and made a new request, and you're right, it's precisely 1 minute that the subsequent request takes.

I was doing this with a Next.js app before, but now I just changed to a simple barebone HTML hello world served with https://github.com/svenstaro/miniserve just to confirm there isn't any funny business going on with this, and there isn't I don't think, exactly the same behaviour

Thanks again, let me know anything else I can do, very happy to conduct further tests, more logs, etc

Edit: forgot to include client log for the above server session, though am pretty sure it's the same pattern as in previous post, but can't hurt.

INFO[0000] waiting for deployment to be ready           
INFO[0003] Waiting for port forward to finish           
INFO[0003] Forwarding from 127.0.0.1:28688 -> 28688
Forwarding from [::1]:28688 -> 28688 
INFO[2020-12-23 09:19:33.754] starting tcp tunnel from source 3000 to target 8080 
DEBU[2020-12-23 09:19:33.792] attempting to receive from stream            
INFO[2020-12-23 09:20:40.576] new connection                                port=8080 session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] received 775 bytes from server                session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] wrote 775 bytes to conn                       session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] started reading conn                          session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] attempting to receive from stream            
DEBU[2020-12-23 09:20:40.577] read 287 bytes from conn                      error="<nil>" session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] wrote 287 bytes to session buf                error="<nil>" session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] read 287 from buffer out of 287 available     session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] sending 287 bytes to server                   close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] sent 287 bytes to server                      close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] read 176 bytes from conn                      error="<nil>" session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] wrote 176 bytes to session buf                error="<nil>" session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] read 176 from buffer out of 176 available     session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] sending 176 bytes to server                   close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.577] sent 176 bytes to server                      close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.664] received 694 bytes from server                session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.664] wrote 694 bytes to conn                       session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.664] attempting to receive from stream            
DEBU[2020-12-23 09:20:40.665] read 2219 bytes from conn                     error="<nil>" session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.665] wrote 2219 bytes to session buf               error="<nil>" session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.665] read 2219 from buffer out of 2219 available   session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.665] sending 2219 bytes to server                  close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:40.665] sent 2219 bytes to server                     close=false session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:20:45.578] finished reading session                      session=37b969b2-948b-4eb0-ae6d-e843f05728b0

// first request went through fine
// below is after I make a second request

DEBU[2020-12-23 09:21:04.073] received 775 bytes from server                session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:21:04.073] wrote 775 bytes to conn                       session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:21:04.073] attempting to receive from stream            

// hangs here for precisely 1 minute

INFO[2020-12-23 09:22:04.068] closed session                                session=37b969b2-948b-4eb0-ae6d-e843f05728b0
DEBU[2020-12-23 09:22:04.069] attempting to receive from stream            
INFO[2020-12-23 09:22:04.069] new connection                                port=8080 session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.069] received 775 bytes from server                session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.069] wrote 775 bytes to conn                       session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.069] attempting to receive from stream            
DEBU[2020-12-23 09:22:04.069] started reading conn                          session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.069] read 287 bytes from conn                      error="<nil>" session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.069] wrote 287 bytes to session buf                error="<nil>" session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.069] read 287 from buffer out of 287 available     session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.069] sending 287 bytes to server                   close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.069] sent 287 bytes to server                      close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.070] read 180 bytes from conn                      error="<nil>" session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.070] wrote 180 bytes to session buf                error="<nil>" session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.070] read 180 from buffer out of 180 available     session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.070] sending 180 bytes to server                   close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.070] sent 180 bytes to server                      close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.162] received 694 bytes from server                session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.162] wrote 694 bytes to conn                       session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.162] attempting to receive from stream            
DEBU[2020-12-23 09:22:04.163] read 2219 bytes from conn                     error="<nil>" session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.163] wrote 2219 bytes to session buf               error="<nil>" session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.163] read 2219 from buffer out of 2219 available   session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.163] sending 2219 bytes to server                  close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:04.163] sent 2219 bytes to server                     close=false session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:22:09.071] finished reading session                      session=f605772e-b1a1-4d52-b9ae-203f4220fafa
INFO[2020-12-23 09:23:04.133] closed session                                session=f605772e-b1a1-4d52-b9ae-203f4220fafa
DEBU[2020-12-23 09:23:04.134] attempting to receive from stream
omrikiei commented 3 years ago

it seems that the 60 seconds are derived from the client (not the ktunnel client, the one that is trying to reach the server over the tunnel), which client are you using to make the requests?

omrikiei commented 3 years ago

@mysterybear is this issue still relevant?

mysterybear commented 3 years ago

@omrikiei Hi, I was using curl as the client, sorry, got caught up with Xmas/NYE!

The problem was also apparent when just using my browser (Chromium) as a client also

I am in the middle of a migration from one cloud provider to another right now though, I guess it will be interesting to see if the problem is still happening on the new provider.

Could keep this open for a few days and I can get back after that, or close and I can re-open if still an issue? Up to you, thanks for your time!

omrikiei commented 3 years ago

Hey @mysterybear, no problem keeping this open.. Happy new year 👍

mysterybear commented 3 years ago

Cheers @omrikiei

I have tried again and am still getting the same behaviour, whether I use curl or the browser as the client, and whether I use miniserve or Next.js as the server.

Usually the first request goes through right away though, but then if I make a change, it's always that next request that hangs for 1 minute.

Can you think of any other tests I can try to find out what's going on, or any other suggestions?

Thanks again!

mysterybear commented 3 years ago

Ah I figured I can post from my ingress logs (grep'd for "error"), I'll just put ***s where I'm obfuscating the domain and *.*.*.* for IP addr's

2021/01/09 09:54:45 [error] 1242#1242: *2692150 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw HTTP/1.1", upstream: "http://*.*.*.*:3000/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw", host: "tunnel.***", referrer: "http://tunnel.***/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw"
2021/01/09 09:54:45 [error] 1242#1242: *2692150 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw HTTP/1.1", upstream: "http://*.*.*.*:3000/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw", host: "tunnel.***", referrer: "http://tunnel.***/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw"
2021/01/09 09:54:45 [error] 1242#1242: *2692150 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw HTTP/1.1", upstream: "http://*.*.*.*:3000/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw", host: "tunnel.***", referrer: "http://tunnel.***/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw"
2021/01/09 09:54:45 [error] 1243#1243: *2692156 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw HTTP/1.1", upstream: "http://*.*.*.*:3000/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw", host: "tunnel.***", referrer: "http://tunnel.***/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw"
2021/01/09 09:54:45 [error] 1243#1243: *2692156 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw HTTP/1.1", upstream: "http://*.*.*.*:3000/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw", host: "tunnel.***", referrer: "http://tunnel.***/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw"
2021/01/09 09:54:45 [error] 1243#1243: *2692156 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw HTTP/1.1", upstream: "http://*.*.*.*:3000/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw", host: "tunnel.***", referrer: "http://tunnel.***/.well-known/acme-challenge/396S_bSJwj4W_bN77DGb4agdb4-Ag2HTetbZfmShDXw"
2021/01/09 09:56:53 [error] 1557#1557: *2693176 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET / HTTP/1.1", upstream: "http://*.*.*.*:3000/", host: "tunnel.***"
2021/01/09 09:56:53 [error] 1557#1557: *2693176 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET / HTTP/1.1", upstream: "http://*.*.*.*:3000/", host: "tunnel.***"
2021/01/09 09:56:53 [error] 1557#1557: *2693176 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET / HTTP/1.1", upstream: "http://*.*.*.*:3000/", host: "tunnel.***"
2021/01/09 09:59:30 [error] 1557#1557: *2693319 upstream timed out (110: Operation timed out) while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /star-pattern.svg HTTP/2.0", upstream: "http://*.*.*.*:3000/star-pattern.svg", host: "tunnel.***", referrer: "https://tunnel.***/"
2021/01/09 09:59:30 [error] 1557#1557: *2693319 upstream timed out (110: Operation timed out) while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /_next/static/development/_devPagesManifest.json HTTP/2.0", upstream: "http://*.*.*.*:3000/_next/static/development/_devPagesManifest.json", host: "tunnel.***", referrer: "https://tunnel.***/"
2021/01/09 10:00:15 [error] 1557#1557: *2693319 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET / HTTP/2.0", upstream: "http://*.*.*.*:3000/", host: "tunnel.***", referrer: "https://tunnel.***/shop"
2021/01/09 10:00:15 [error] 1557#1557: *2693319 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET / HTTP/2.0", upstream: "http://*.*.*.*:3000/", host: "tunnel.***", referrer: "https://tunnel.***/shop"
2021/01/09 10:00:15 [error] 1557#1557: *2693319 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET / HTTP/2.0", upstream: "http://*.*.*.*:3000/", host: "tunnel.***", referrer: "https://tunnel.***/shop"
2021/01/09 10:00:15 [error] 1557#1557: *2693319 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /favicon.ico HTTP/2.0", upstream: "http://*.*.*.*:3000/favicon.ico", host: "tunnel.***", referrer: "https://tunnel.***/"
2021/01/09 10:00:15 [error] 1557#1557: *2693319 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /favicon.ico HTTP/2.0", upstream: "http://*.*.*.*:3000/favicon.ico", host: "tunnel.***", referrer: "https://tunnel.***/"
2021/01/09 10:00:15 [error] 1557#1557: *2693319 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET /favicon.ico HTTP/2.0", upstream: "http://*.*.*.*:3000/favicon.ico", host: "tunnel.***", referrer: "https://tunnel.***/"
2021/01/09 10:03:01 [error] 1557#1557: *2693319 upstream timed out (110: Operation timed out) while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET / HTTP/2.0", upstream: "http://*.*.*.*:3000/", host: "tunnel.***", referrer: "https://tunnel.***/shop"

@omrikiei

mysterybear commented 3 years ago

less noisy version with just a single index.html served using miniserve:

*.*.*.* - - [09/Jan/2021:10:18:17 +0000] "GET / HTTP/2.0" 304 0 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/*.*.*.* Safari/537.36" 380 0.031 [ktunnel-ktunnel-3000] [] *.*.*.*:3000 0 0.029 304 3647965a8d270fb96f42bb1e127790e0

2021/01/09 10:19:30 [error] 1556#1556: *2701427 upstream timed out (110: Operation timed out) while reading response header from upstream, client: *.*.*.*, server: tunnel.***, request: "GET / HTTP/2.0", upstream: "http://*.*.*.*:3000/", host: "tunnel.***"
*.*.*.* - - [09/Jan/2021:10:19:30 +0000] "GET / HTTP/2.0" 200 173 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/*.*.*.* Safari/537.36" 35 60.036 [ktunnel-ktunnel-3000] [] *.*.*.*:3000, *.*.*.*:3000 0, 184 60.002, 0.032 504, 200 c9e33c25b9fd2d56686170ac849aa4e1

(the logs in the previous example were tunnelling a full Next.js site)

omrikiei commented 3 years ago

Hi @mysterybear, I authored a new beta version that closes the connection from the client on EOF - I think this is what caused the connection to hang... would you mind trying to work with this beta? if it works I'll release it as a fix... You can find it here or build it from this branch. Please let me know if the issue persists after working with this version. Thank you for using ktunnel, and thank you for your feedback.

mysterybear commented 3 years ago

@omrikiei Hey this is working wonderfully now, tyvm!

One thing though, I did have to run the client with -i quay.io/omrikiei/ktunnel:v1.3.3-beta because by default it tries to find the tag 1.3.3-beta (no 'v'!).

omrikiei commented 3 years ago

@mysterybear thank you again for your feedback, fixed versioning tags issue as well and released v1.3.3 closing this