[MAISTRA-1810] Check delayed close expiry to prevent possible early close

Type: Task
Resolution: Done
Priority: Major
Fix Version/s: maistra-1.1.8
Affects Version/s: None
Component/s: None
Labels:
None

Git Pull Request:
https://github.com/maistra/envoy/pull/40

Sprint:
MAISTRA 1.1.8

SFDC Cases Counter:
SFDC Cases Open:
SFDC Cases Links:

We are sometimes seeing traces which show "write flush complete" logs within the timeout period for close. These are likely associated with a subsequent write event, after the write has taken place, but do not extend the grace period for close.

This happens under load and likely means that the timeout has already triggered, we should tolerate this event and extend the grace period as the code intends.

is cloned by

MAISTRA-1860 Check delayed close expiry to prevent possible early close

Closed

Kevin Conner (Inactive) added a comment - 2020/10/13 10:48 AM

bravery300 There is no reliable reproducer for this issue, we just have the logs which show that the close was triggered earlier than the 1s as required.

Kevin Conner (Inactive) added a comment - 2020/10/13 10:48 AM bravery300 There is no reliable reproducer for this issue, we just have the logs which show that the close was triggered earlier than the 1s as required.

Brian Avery (Inactive) added a comment - 2020/10/12 3:54 PM

kconner@redhat.com ddolguik-ocp how was this reproduced?

Brian Avery (Inactive) added a comment - 2020/10/12 3:54 PM kconner@redhat.com ddolguik-ocp how was this reproduced?

Kevin Conner (Inactive) added a comment - 2020/09/09 1:32 PM

This is an example of the trace we are seeing

trigger/thread.C198470:[Envoy (Epoch 0)] [2020-08-31 21:29:45.594][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:670] [C198470] triggered delayed c[Envoy (Epoch 0)] [2020-08-31 21:22:42.662][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:483] [C25776] socket event: 3
[Envoy (Epoch 0)] [2020-08-31 21:22:42.662][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:571] [C25776] write ready
[Envoy (Epoch 0)] [2020-08-31 21:22:42.663][23][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C25776] handshake expecting read
[Envoy (Epoch 0)] [2020-08-31 21:22:42.663][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:521] [C25776] read ready
[Envoy (Epoch 0)] [2020-08-31 21:22:42.663][23][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C25776] handshake expecting read
[Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:483] [C25776] socket event: 3
[Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:571] [C25776] write ready
[Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:176] [C25776] handshake complete
[Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:521] [C25776] read ready
[Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C25776] ssl read returns: 161
[Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C25776] ssl read returns: -1
[Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:155] [C25776] ssl read 161 bytes into 1 slices
[Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:298] [C25776] readDisable: enabled=true disable=true state=0
[Envoy (Epoch 0)] [2020-08-31 21:22:44.195][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:483] [C25776] socket event: 2
[Envoy (Epoch 0)] [2020-08-31 21:22:44.195][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:571] [C25776] write ready
[Envoy (Epoch 0)] [2020-08-31 21:22:44.545][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:419] [C25776] writing 1044 bytes, end_stream false
[Envoy (Epoch 0)] [2020-08-31 21:22:44.545][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:419] [C25776] writing 2680 bytes, end_stream false
[Envoy (Epoch 0)] [2020-08-31 21:22:44.545][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:419] [C25776] writing 5 bytes, end_stream false
[Envoy (Epoch 0)] [2020-08-31 21:22:44.545][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:104] [C25776] closing data_to_write=3729 type=2
[Envoy (Epoch 0)] [2020-08-31 21:22:44.545][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:681] [C25776] setting delayed close timer with timeout 1000 ms
[Envoy (Epoch 0)] [2020-08-31 21:22:45.035][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:483] [C25776] socket event: 2
[Envoy (Epoch 0)] [2020-08-31 21:22:45.035][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:571] [C25776] write ready
[Envoy (Epoch 0)] [2020-08-31 21:22:45.035][23][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:263] [C25776] ssl write returns: 3729
[Envoy (Epoch 0)] [2020-08-31 21:22:45.035][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:610] [C25776] write flush complete
[Envoy (Epoch 0)] [2020-08-31 21:22:46.930][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:483] [C25776] socket event: 2
[Envoy (Epoch 0)] [2020-08-31 21:22:46.930][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:571] [C25776] write ready
[Envoy (Epoch 0)] [2020-08-31 21:22:46.930][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:610] [C25776] write flush complete
[Envoy (Epoch 0)] [2020-08-31 21:22:47.257][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:670] [C25776] triggered delayed close
[Envoy (Epoch 0)] [2020-08-31 21:22:47.258][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:193] [C25776] closing socket: 1
[Envoy (Epoch 0)] [2020-08-31 21:22:47.258][23][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:302] [C25776] SSL shutdown: rc=-1
[Envoy (Epoch 0)] [2020-08-31 21:22:47.258][23][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:230] [C25776]

The second flush should extend the timeout from that point (21:22:46.930) but the trigger happens at 21:22:47.257 which is 327 ms later.

Kevin Conner (Inactive) added a comment - 2020/09/09 1:32 PM This is an example of the trace we are seeing trigger/thread.C198470:[Envoy (Epoch 0)] [2020-08-31 21:29:45.594][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:670] [C198470] triggered delayed c[Envoy (Epoch 0)] [2020-08-31 21:22:42.662][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:483] [C25776] socket event: 3 [Envoy (Epoch 0)] [2020-08-31 21:22:42.662][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:571] [C25776] write ready [Envoy (Epoch 0)] [2020-08-31 21:22:42.663][23][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C25776] handshake expecting read [Envoy (Epoch 0)] [2020-08-31 21:22:42.663][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:521] [C25776] read ready [Envoy (Epoch 0)] [2020-08-31 21:22:42.663][23][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:191] [C25776] handshake expecting read [Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:483] [C25776] socket event: 3 [Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:571] [C25776] write ready [Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:176] [C25776] handshake complete [Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:521] [C25776] read ready [Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C25776] ssl read returns: 161 [Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:80] [C25776] ssl read returns: -1 [Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:155] [C25776] ssl read 161 bytes into 1 slices [Envoy (Epoch 0)] [2020-08-31 21:22:42.949][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:298] [C25776] readDisable: enabled=true disable=true state=0 [Envoy (Epoch 0)] [2020-08-31 21:22:44.195][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:483] [C25776] socket event: 2 [Envoy (Epoch 0)] [2020-08-31 21:22:44.195][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:571] [C25776] write ready [Envoy (Epoch 0)] [2020-08-31 21:22:44.545][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:419] [C25776] writing 1044 bytes, end_stream false [Envoy (Epoch 0)] [2020-08-31 21:22:44.545][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:419] [C25776] writing 2680 bytes, end_stream false [Envoy (Epoch 0)] [2020-08-31 21:22:44.545][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:419] [C25776] writing 5 bytes, end_stream false [Envoy (Epoch 0)] [2020-08-31 21:22:44.545][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:104] [C25776] closing data_to_write=3729 type=2 [Envoy (Epoch 0)] [2020-08-31 21:22:44.545][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:681] [C25776] setting delayed close timer with timeout 1000 ms [Envoy (Epoch 0)] [2020-08-31 21:22:45.035][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:483] [C25776] socket event: 2 [Envoy (Epoch 0)] [2020-08-31 21:22:45.035][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:571] [C25776] write ready [Envoy (Epoch 0)] [2020-08-31 21:22:45.035][23][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:263] [C25776] ssl write returns: 3729 [Envoy (Epoch 0)] [2020-08-31 21:22:45.035][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:610] [C25776] write flush complete [Envoy (Epoch 0)] [2020-08-31 21:22:46.930][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:483] [C25776] socket event: 2 [Envoy (Epoch 0)] [2020-08-31 21:22:46.930][23][trace][connection] [external/envoy/source/common/network/connection_impl.cc:571] [C25776] write ready [Envoy (Epoch 0)] [2020-08-31 21:22:46.930][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:610] [C25776] write flush complete [Envoy (Epoch 0)] [2020-08-31 21:22:47.257][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:670] [C25776] triggered delayed close [Envoy (Epoch 0)] [2020-08-31 21:22:47.258][23][debug][connection] [external/envoy/source/common/network/connection_impl.cc:193] [C25776] closing socket: 1 [Envoy (Epoch 0)] [2020-08-31 21:22:47.258][23][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:302] [C25776] SSL shutdown: rc=-1 [Envoy (Epoch 0)] [2020-08-31 21:22:47.258][23][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:230] [C25776] The second flush should extend the timeout from that point (21:22:46.930) but the trigger happens at 21:22:47.257 which is 327 ms later.

Details

Description

Attachments

Issue Links

Easy Agile Planning Poker

Activity

Collapse comment: Kevin Conner (Inactive) added a comment - 2020/10/13 10:48 AM

Expand comment: Kevin Conner (Inactive) added a comment - 2020/10/13 10:48 AM

Collapse comment: Brian Avery (Inactive) added a comment - 2020/10/12 3:54 PM

Expand comment: Brian Avery (Inactive) added a comment - 2020/10/12 3:54 PM

Collapse comment: Kevin Conner (Inactive) added a comment - 2020/09/09 1:32 PM

Expand comment: Kevin Conner (Inactive) added a comment - 2020/09/09 1:32 PM

People

Dates