integration with ADFS fails due to unable to shutdown connection for ssl stream

[incfly]

Documented an issue we are trying to fix.

Scenario: An ADFS server act as IdP; auth service configured with client id/secret as usual.
End user observed behavior: redirection is fine, but authservice can't reach out to idp to get id token, therefore HTTP request fails

In the authservice.log, looking at the following snippet shows the initial call to RetrieveToken,
connecting to ADFS, and then 2 minutes of waiting until RetrieveToken returns:

[2022-03-22 16:26:38.188] [console] [trace] RetrieveToken
[2022-03-22 16:26:38.188] [console] [trace] Post
[2022-03-22 16:26:38.528] [console] [info] Post: Trusting the provided certificate authority
[2022-03-22 16:26:38.530] [console] [info] Post: opening connection to https://adfs.example.com:443
[2022-03-22 16:27:26.823] [console] [info] operator(): Starting periodic cleanup (period of 60 seconds)
[2022-03-22 16:27:26.823] [console] [info] DoPeriodicCleanup: removing expired sessions from chain kafdrop
[2022-03-22 16:27:26.823] [console] [info] DoPeriodicCleanup: removing expired sessions from chain nifi
[2022-03-22 16:27:26.823] [console] [info] DoPeriodicCleanup: removing expired sessions from chain nifi-registry
[2022-03-22 16:28:26.823] [console] [info] operator(): Starting periodic cleanup (period of 60 seconds)
[2022-03-22 16:28:26.823] [console] [info] DoPeriodicCleanup: removing expired sessions from chain kafdrop
[2022-03-22 16:28:26.823] [console] [info] DoPeriodicCleanup: removing expired sessions from chain nifi
[2022-03-22 16:28:26.823] [console] [info] DoPeriodicCleanup: removing expired sessions from chain nifi-registry
[2022-03-22 16:28:42.787] [console] [info] RetrieveToken: Saving token response to session store

Looking at the Istio sidecar logs within the same timeframe (begin: 2022-03-22T16:26:38.620989Z) shows the following:
2022-03-22T16:26:38.620989Z debug envoy filter original_dst: New connection accepted
2022-03-22T16:26:38.621109Z debug envoy filter [C442] new tcp proxy session
2022-03-22T16:26:38.621128Z trace envoy connection [C442] readDisable: disable=true disable_count=0 state=0 buffer_length=0
2022-03-22T16:26:38.621151Z debug envoy filter [C442] Creating connection to cluster PassthroughCluster
2022-03-22T16:26:38.621188Z debug envoy upstream transport socket match, socket default selected for host with address 100.0.0.1:443
2022-03-22T16:26:38.621194Z debug envoy upstream Created host 100.0.0.1:443.
2022-03-22T16:26:38.621219Z debug envoy pool creating a new connection
2022-03-22T16:26:38.621239Z debug envoy upstream addHost() adding 100.0.0.1:443
2022-03-22T16:26:38.621273Z debug envoy pool [C443] connecting
2022-03-22T16:26:38.621290Z debug envoy connection [C443] connecting to 100.0.0.1:443
2022-03-22T16:26:38.621294Z debug envoy upstream membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-03-22T16:26:38.621301Z debug envoy upstream re-creating local LB for TLS cluster PassthroughCluster
2022-03-22T16:26:38.621306Z debug envoy upstream membership update for TLS cluster PassthroughCluster added 1 removed 0
2022-03-22T16:26:38.621318Z debug envoy upstream re-creating local LB for TLS cluster PassthroughCluster
2022-03-22T16:26:38.621365Z debug envoy connection [C443] connection in progress
2022-03-22T16:26:38.621399Z debug envoy pool queueing request due to no available connections
2022-03-22T16:26:38.621404Z debug envoy conn_handler [C442] new connection from 10.42.22.84:51336

C442 is the connection from Istio to authservice (authservice pod ip/port: 10.42.22.84:51336)
C443 is the connection from Istio to ADFS (100.0.0.1:443)

Looking at the istio-proxy (sidecar) logs:
--- Lines 50550-50648 all occur at timestamp 2022-03-22T16:26:38 ---
Line 50581: C442 reads 191 bytes (from authservice)
Line 50585: C443 writes 191 bytes (to ADFS)
Line 50592: C443 reads 3047 bytes (from ADFS)
Line 50595: C442 writes 3047 bytes (to authservice)
Line 50602: C442 reads 126 bytes (from authservice)
Line 50605: C443 writes 126 bytes (to ADFS)
Line 50612: C443 reads 51 bytes (from ADFS)
Line 50615: C442 writes 51 bytes (to authservice)
Line 50622: C442 reads 827 bytes (from authservice)
Line 50625: C443 writes 827 bytes (to ADFS)
Line 50632: C443 reads 5468 bytes (from ADFS)
Line 50635: C442 writes 5468 bytes (to authservice)
Line 50642: C442 reads 31 bytes (from authservice)
Line 50645: C443 writes 31 bytes (to ADFS)
--- NO RESPONSE FROM ADFS for 120+ seconds, until 2022-03-22T16:28:42 ---
Line 58343: C443 read error: Connection reset by peer (ADFS closed the connection)
Line 58345: C443 closing socket
Line 58347: C443 client disconnected
Line 58351: C442 closing socket (connection to authservice closed)

Back to the authservice.log (notice that authservice doesn't exit the RetrieveToken method and begin
processing the JWT until the connection to ADFS is closed at 16:28:42):

[2022-03-22 16:28:42.787] [console] [info] RetrieveToken: Saving token response to session store
[2022-03-22 16:28:42.788] [console] [trace] Request processing complete
[2022-03-22 16:28:42.788] [console] [trace] Processing completion and deleting state
[2022-03-22 16:28:42.887] [console] [trace] Creating V3 request processor state
[2022-03-22 16:28:42.887] [console] [trace] Launching request processor worker
[2022-03-22 16:28:42.887] [console] [trace] Processing request
[2022-03-22 16:28:42.887] [console] [trace] Check
[2022-03-22 16:28:42.887] [console] [trace] Matches
[2022-03-22 16:28:42.887] [console] [debug] Check: processing request https://example.com/foo with filter chain kafdrop
[2022-03-22 16:28:42.887] [console] [trace] New
[2022-03-22 16:28:42.887] [console] [trace] OidcFilter
[2022-03-22 16:28:42.887] [console] [trace] Process
[2022-03-22 16:28:42.887] [console] [debug] Call from spiffe://cluster.local/ns/istio-system/sa/[email protected] to spiffe://cluster.local/ns/int/sa/[email protected]
[2022-03-22 16:28:42.887] [console] [trace] MatchesCallbackRequest: checking handler for https://example.com/foo
[2022-03-22 16:28:42.887] [console] [trace] MatchesCallbackRequest: matches_callback: false
[2022-03-22 16:28:42.887] [console] [trace] Process: attempting session retrieval
[2022-03-22 16:28:42.887] [console] [trace] Process: checking retrieved token response for expected tokens
[2022-03-22 16:28:42.888] [console] [trace] Process: checking token expiration
[2022-03-22 16:28:42.888] [console] [info] Process: Tokens not expired. Allowing request to proceed.
[2022-03-22 16:28:42.888] [console] [trace] Request processing complete
[2022-03-22 16:28:42.888] [console] [trace] Processing completion and deleting state

[incfly]

After looking a bit, I found it could be that async_shutdown

authservice/src/common/http/http.cc

Line 637 in 6023610

stream.async_shutdown(yield[ec]);

This sends close_notify from client side to the server. but the server would not participate with close.
from the logic view, we don't really need to wait for that.

[incfly]

some relevant thread https://stackoverflow.com/questions/32046034/what-is-the-proper-way-to-securely-disconnect-an-asio-ssl-socket