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.

Sign up for GitHub

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

Jump to bottom

the ssl connection can not be closed when the status is NEED_UNWRAP #11256

Closed
luffy1949 opened this issue Jan 9, 2024 · 12 comments
Closed

the ssl connection can not be closed when the status is NEED_UNWRAP #11256

luffy1949 opened this issue Jan 9, 2024 · 12 comments
Labels
End-of-Life release Question

Comments

@luffy1949
Copy link

Jetty version(s)
Jetty 9.4.48.v20220622
Jetty Environment

Java version/vendor (use: java -version)
JDK8
OS type/version
suse 12.5
Description

4.252.83.81 is client
11.19.120.119 is server
when the server send the "server hello" ,we hope the client replay a "key exchange" package ,but the client just replayed an ACK ,so The SSL connection on the server is suspended.
we looked at the dump file ,all pending connections are in the "NEED_UNWRAP" state.

we want to know if jetty has a protection mechanism for this scenario

How to reproduce?

capture
@luffy1949 luffy1949 added the Bug For general bugs on Jetty side label Jan 9, 2024
@sbordet
Copy link
Contributor

sbordet commented Jan 9, 2024

Jetty versions 9, 10 and 11 are at End of Community Support, see #7958 and #10485.
You should upgrade to Jetty 12.

@sbordet
Copy link
Contributor

sbordet commented Jan 9, 2024

we want to know if jetty has a protection mechanism for this scenario

Yes, the connection will eventually idle timeout and be closed.

@sbordet sbordet added Question and removed Bug For general bugs on Jetty side labels Jan 9, 2024
@luffy1949
Copy link
Author

idle timeout is 10min，but the connection is always in the ESTABLISHED state

idleTimeout

@sbordet
Copy link
Contributor

sbordet commented Jan 9, 2024

The connection will in ESTABLISHED for 10 minutes, then it will get closed.

@luffy1949
Copy link
Author

Actually, the connection is not closed

@sbordet
Copy link
Contributor

sbordet commented Jan 9, 2024

We need hard evidence that this is not the case.

The server will idle timeout and will try to send the client a TLS close alert and a TCP FIN.
The client is supposed to answer with a TCP FIN, and the server will close the connection.

If the client does not answer the TCP FIN, after another idle timeout the server will close the connection.

If you have hard evidence that this is not the case, please report the server's DEBUG logs.

@joakime
Copy link
Contributor

joakime commented Jan 9, 2024

If you have hard evidence that this is not the case, please report the server's DEBUG logs.

But only from a supported version of Jetty.

@luffy1949
Copy link
Author

luffy1949 commented Jan 11, 2024 •
edited by sbordet
Loading

The DEBUG logs:

2024-01-11 17:05:44,688 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 161||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=599949/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=599950/600000}=>HTTP2ServerConnection@27500ac4 idle timeout check, elapsed: 599949 ms, remaining: 51 ms
2024-01-11 17:05:44,739 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 161||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600001/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600001/600000}=>HTTP2ServerConnection@27500ac4 idle timeout check, elapsed: 600001 ms, remaining: -1 ms
2024-01-11 17:05:44,739 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 168||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600001/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600002/600000}=>HTTP2ServerConnection@27500ac4 idle timeout expired
2024-01-11 17:05:44,739 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Session 1827||||Idle timeout confirmed for HTTP2ServerSession@53458d66{local:/10.136.184.107:10032,remote:/10.136.110.199:63137,sendWindow=65535,recvWindow=65535,state=[streams=0,NOT_CLOSED,goAwayRecv=null,goAwaySent=null,failure=null]}
2024-01-11 17:05:44,739 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Session 1570||||Halting (idle_timeout) for HTTP2ServerSession@53458d66{local:/10.136.184.107:10032,remote:/10.136.110.199:63137,sendWindow=65535,recvWindow=65535,state=[streams=0,NOT_CLOSED,goAwayRecv=null,goAwaySent=null,failure=null]}
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Session 722||||Sending GoAwayFrame@5a666ce2{0/no_error/idle_timeout} on HTTP2ServerSession@53458d66{local:/10.136.184.107:10032,remote:/10.136.110.199:63137,sendWindow=65535,recvWindow=65535,state=[streams=0,CLOSED,goAwayRecv=null,goAwaySent=GoAwayFrame@5a666ce2{0/no_error/idle_timeout},failure=null]}
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Flusher 116||||Appended GoAwayFrame@5a666ce2{0/no_error/idle_timeout}, entries=1
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Flusher 164||||Flushing HTTP2ServerSession@53458d66{local:/10.136.184.107:10032,remote:/10.136.110.199:63137,sendWindow=65535,recvWindow=65535,state=[streams=0,CLOSED,goAwayRecv=null,goAwaySent=GoAwayFrame@5a666ce2{0/no_error/idle_timeout},failure=null]}
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Flusher 203||||Processing GoAwayFrame@5a666ce2{0/no_error/idle_timeout}
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Flusher 221||||Generated 29 frame bytes for GoAwayFrame@5a666ce2{0/no_error/idle_timeout}
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Flusher 287||||Writing 1 buffers (29 bytes) - entries processed/pending 1/0: [GoAwayFrame@5a666ce2{0/no_error/idle_timeout}]/[]
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.WriteFlusher 270||||write: WriteFlusher@ebfbb24{IDLE}->null [DirectByteBuffer@4563885c[p=0,l=29,c=1024,r=29]={<<<\\x00\\x00\\x14\\x07\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00idle_timeout>>>\\x00\\x00 \\x00\\x00\\x00\\x00\\x00\\x00...\\x00\\x00\\x00\\x00\\x00\\x00\\x00}]
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.WriteFlusher 112||||update WriteFlusher@ebfbb24{WRITING}->null:IDLE-->WRITING
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.s.SslConnection 1008||||>flush SslConnection@29fbae6c::SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600002/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=W,to=600003/600000}=>HTTP2ServerConnection@27500ac4
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.s.SslConnection 1012||||flush b[0]=DirectByteBuffer@4563885c[p=0,l=29,c=1024,r=29]={<<<\\x00\\x00\\x14\\x07\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00idle_timeout>>>\\x00\\x00 \\x00\\x00\\x00\\x00\\x00\\x00...\\x00\\x00\\x00\\x00\\x00\\x00\\x00}
2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.s.SslConnection 1044||||flush NEED_UNWRAP
2024-01-11 17:05:44,741 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.s.SslConnection 1194||||<flush false SslConnection@29fbae6c::SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600003/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=W,to=600003/600000}=>HTTP2ServerConnection@27500ac4
2024-01-11 17:05:44,741 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.WriteFlusher 427||||Flushed=false written=0 remaining=29 WriteFlusher@ebfbb24{WRITING}->null
2024-01-11 17:05:44,741 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.WriteFlusher 465||||!fully flushed WriteFlusher@ebfbb24{WRITING}->null
2024-01-11 17:05:44,741 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.WriteFlusher 282||||flushed incomplete
2024-01-11 17:05:44,741 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.WriteFlusher 112||||update WriteFlusher@ebfbb24{PENDING}->HTTP2Flusher@770b6b81[PROCESSING][window_queue=0,frame_queue=0,processed/pending=1/0]:WRITING-->PENDING
2024-01-11 17:05:44,741 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.s.SslConnection 1217||||>onIncompleteFlush SslConnection@29fbae6c::SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600003/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=IDLE}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=P,to=600004/600000}=>HTTP2ServerConnection@27500ac4 null
2024-01-11 17:05:44,741 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.s.SslConnection 1283||||<onIncompleteFlush s=WAIT_FOR_FILL/INTERESTED fi=false w=null



2024-01-11 17:15:44,742 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 161||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600000/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=WAIT_FOR_FILL}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=P,to=1200004/600000}=>HTTP2ServerConnection@27500ac4 idle timeout check, elapsed: 600000 ms, remaining: 0 ms
2024-01-11 17:15:44,742 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 168||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600000/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=WAIT_FOR_FILL}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=P,to=1200004/600000}=>HTTP2ServerConnection@27500ac4 idle timeout expired
2024-01-11 17:15:44,742 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Session 1817||||Already closed, ignored idle timeout for HTTP2ServerSession@53458d66{local:/10.136.184.107:10032,remote:/10.136.110.199:63137,sendWindow=65535,recvWindow=65535,state=[streams=0,CLOSED,goAwayRecv=null,goAwaySent=GoAwayFrame@5a666ce2{0/no_error/idle_timeout},failure=null]}




2024-01-11 17:25:44,742 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 161||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600000/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=WAIT_FOR_FILL}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=P,to=1800005/600000}=>HTTP2ServerConnection@27500ac4 idle timeout check, elapsed: 600000 ms, remaining: 0 ms
2024-01-11 17:25:44,742 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 168||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600000/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=WAIT_FOR_FILL}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=P,to=1800005/600000}=>HTTP2ServerConnection@27500ac4 idle timeout expired
2024-01-11 17:25:44,743 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Session 1817||||Already closed, ignored idle timeout for HTTP2ServerSession@53458d66{local:/10.136.184.107:10032,remote:/10.136.110.199:63137,sendWindow=65535,recvWindow=65535,state=[streams=0,CLOSED,goAwayRecv=null,goAwaySent=GoAwayFrame@5a666ce2{0/no_error/idle_timeout},failure=null]}




2024-01-11 17:35:44,743 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 161||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600000/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=WAIT_FOR_FILL}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=P,to=2400005/600000}=>HTTP2ServerConnection@27500ac4 idle timeout check, elapsed: 600000 ms, remaining: 0 ms
2024-01-11 17:35:44,743 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 168||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600000/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=WAIT_FOR_FILL}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=P,to=2400005/600000}=>HTTP2ServerConnection@27500ac4 idle timeout expired
2024-01-11 17:35:44,743 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Session 1817||||Already closed, ignored idle timeout for HTTP2ServerSession@53458d66{local:/10.136.184.107:10032,remote:/10.136.110.199:63137,sendWindow=65535,recvWindow=65535,state=[streams=0,CLOSED,goAwayRecv=null,goAwaySent=GoAwayFrame@5a666ce2{0/no_error/idle_timeout},failure=null]}




2024-01-11 17:45:44,744 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 161||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600000/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=WAIT_FOR_FILL}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=P,to=3000006/600000}=>HTTP2ServerConnection@27500ac4 idle timeout check, elapsed: 600000 ms, remaining: 0 ms
2024-01-11 17:45:44,744 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.i.IdleTimeout 168||||SocketChannelEndPoint@14dd828c{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=-,to=600000/600000}{io=1/1,kio=1,kro=1}->SslConnection@29fbae6c{NEED_UNWRAP,eio=-1/-1,di=-1,fill=INTERESTED,flush=WAIT_FOR_FILL}~>DecryptedEndPoint@58f9e1c9{l=/10.136.184.107:10032,r=/10.136.110.199:63137,OPEN,fill=FI,flush=P,to=3000006/600000}=>HTTP2ServerConnection@27500ac4 idle timeout expired
2024-01-11 17:45:44,744 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Session 1817||||Already closed, ignored idle timeout for HTTP2ServerSession@53458d66{local:/10.136.184.107:10032,remote:/10.136.110.199:63137,sendWindow=65535,recvWindow=65535,state=[streams=0,CLOSED,goAwayRecv=null,goAwaySent=GoAwayFrame@5a666ce2{0/no_error/idle_timeout},failure=null]}

@joakime
Copy link
Contributor

joakime commented Jan 11, 2024

Please collect the ENTIRE DEBUG logs from a supported version of Jetty, do not remove lines, but feel free to change/edit out sensitive data in a line, or remove lines not from org.eclipse.jetty. loggers.

@joakime
Copy link
Contributor

joakime commented Jan 11, 2024 

2024-01-11 17:05:44,740 DEBUG|Connector-Scheduler-688d65a9-1|o.e.j.h.HTTP2Flusher 116||||Appended GoAwayFrame@5a666ce2{0/no_error/idle_timeout}, entries=1

This class does not exist in Jetty 12 (the only community supported version of Jetty right now) - that class was reworked and moved to a new location.

Upgrade and try again with a supported version of Jetty, if the problem persists collect the ENTIRE DEBUG LOGS and report back.

@joakime
Copy link
Contributor

joakime commented Jan 11, 2024 •
edited
Loading

I am closing this issue due to it being on an unsupported version of Jetty.

When you have upgraded, and if you are still having the issue, either comment here and we will reopen this issue, or open a new issue.

@joakime joakime closed this as not planned Won't fix, can't repro, duplicate, stale Jan 11, 2024
@sbordet sbordet mentioned this issue Jan 11, 2024
Closed
@sbordet
Copy link
Contributor

sbordet commented Jan 11, 2024

@luffy1949 I opened #11259 to fix this issue, which I think affects later versions as well.

@github-actions github-actions bot mentioned this issue Feb 29, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
End-of-Life release Question
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@joakime @sbordet @luffy1949