Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Subsequent requests hang for exactly 1 minute #36

Closed
mysterybear opened this issue Dec 22, 2020 · 14 comments
Closed

Subsequent requests hang for exactly 1 minute #36

mysterybear opened this issue Dec 22, 2020 · 14 comments

Comments

@mysterybear
Copy link

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
Copy link
Owner

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

@mysterybear
Copy link
Author

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
Copy link
Owner

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
Copy link
Author

mysterybear commented Dec 23, 2020

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

@mysterybear mysterybear changed the title Requests intermittently very slow Subsequent requests hang for exactly 1 minute Dec 23, 2020
@omrikiei
Copy link
Owner

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
Copy link
Owner

omrikiei commented Jan 3, 2021

@mysterybear is this issue still relevant?

@mysterybear
Copy link
Author

@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
Copy link
Owner

omrikiei commented Jan 3, 2021

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

@mysterybear
Copy link
Author

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
Copy link
Author

mysterybear commented Jan 9, 2021

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
Copy link
Author

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
Copy link
Owner

omrikiei commented Jan 9, 2021

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
Copy link
Author

@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
Copy link
Owner

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants