Linkerd2: Transient OpenSSL errors when Linkerd is injected (no peer certificate available) (SSLv3/TLS write client hello)
Bug Report
What is the issue?
When Linkerd2 sidecar is injected, periodically requests to _external_ endpoints fail with SSL errors.
In Ruby the issue looks like:
OpenSSL::SSL::SSLError: SSL_connect SYSCALL returned=5 errno=0 state=SSLv3/TLS write client helloIn linkerd-debug no visible symptoms
In openssl cli the error starts from the message
no peer certificate available
How can it be reproduced?
Start a new pod with the injected sidecar with a command that does nothing (tail -f /dev/null).
Exec inside and run the following script:
#!/usr/bin/env bash
echo "" > out_2
while :
do
echo "*****" >> out_2
echo "GET /" | openssl s_client -connect www.example.com:443 -no_tls1_1 >> out_2 # -no_tls1_1 is not required to reproduce the error
# curl -vvv https://bing.com/ >> out_2 2>&1
# wget -O- https://google.com >/dev/null
ret=$?
if [ $ret -ne 0 ]; then
echo "!!!!!!" >> out_2
exit
fi
done
Logs, error output, etc
Here are output results from the script. A good result includes server certificate chain. A bad one includes no peer certificate available.
https://gist.github.com/KIVagant/37b87245b27810f359acb22fdfa4c13b
When linkerd proxy is uninjected, the error never appears.
linkerd check output
# all is green, except the version is not the latest available
‼ control plane is up-to-date
is running version 2.7.1 but the latest stable version is 2.8.1
see https://linkerd.io/checks/#l5d-version-control for hints
Environment
- Kubernetes Version:
Server Version: version.Info{Major:"1", Minor:"14+", GitVersion:"v1.14.9-eks-f459c0" - Cluster Environment: EKS
- Host OS: Amazon Linux
- Linkerd version:
Client version: stable-2.7.1
Server version: stable-2.7.1
Possible solution
Additional context
We see the issue in many applications, it appears in many places hundreds of times a day randomly.
Also we never saw this with Linkerd v1
KIVagant
All 17 comments
@KIVagant Thanks for the concise repro! We'll take a look at this.
olix0r
on 3 Aug 2020
Possibly relevant https://github.com/linkerd/linkerd2/issues/4308.
ihcsim
on 7 Aug 2020
If it is possible, I would really ask you to prioritize this. The issue hits us hard every day and I don't see any workarounds. :(
KIVagant
on 7 Aug 2020
@KIVagant Will skipping the outbound tls port help in this case?
ihcsim
on 7 Aug 2020
I just read this suggestion and I'm going to try this today.
Up: the workaround seems to be working. I'm not happy to disable Linkerd but at least this will reduce the criticality. Thank you!
KIVagant
on 7 Aug 2020
I believe I've managed to reproduce this with curl, using Linkerd stable-2.8.1. After several successful requests, curl fails with this output (I copied the last successful request as well):
*****
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Trying 13.107.21.200...
* TCP_NODELAY set
* Connected to bing.com (13.107.21.200) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
* CAfile: /etc/ssl/certs/ca-certificates.crt
CApath: /etc/ssl/certs
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
} [5 bytes data]
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.2 (IN), TLS handshake, Server hello (2):
{ [90 bytes data]
* TLSv1.2 (IN), TLS handshake, Certificate (11):
{ [5059 bytes data]
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
{ [365 bytes data]
* TLSv1.2 (IN), TLS handshake, Server finished (14):
{ [4 bytes data]
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
} [102 bytes data]
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
} [1 bytes data]
* TLSv1.2 (OUT), TLS handshake, Finished (20):
} [16 bytes data]
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
{ [1 bytes data]
* TLSv1.2 (IN), TLS handshake, Finished (20):
{ [16 bytes data]
* SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384
* ALPN, server accepted to use h2
* Server certificate:
* subject: CN=www.bing.com
* start date: Apr 30 20:48:00 2019 GMT
* expire date: Apr 30 20:48:00 2021 GMT
* subjectAltName: host "bing.com" matched cert's "bing.com"
* issuer: C=US; ST=Washington; L=Redmond; O=Microsoft Corporation; OU=Microsoft IT; CN=Microsoft IT TLS CA 2
* SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x5652a98cfea0)
} [5 bytes data]
> GET / HTTP/1.1
> Host: bing.com
> User-Agent: curl/7.52.1
> Accept: */*
>
{ [5 bytes data]
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
} [5 bytes data]
< HTTP/2 301
< cache-control: private
< content-length: 193
< content-type: text/html; charset=utf-8
< location: https://www.bing.com:443/?toWww=1&redig=1FC8450CDBF44B4E8EE2E9B68674DD24
< strict-transport-security: max-age=31536000; includeSubDomains; preload
< x-msedge-ref: Ref A: 9AE2CF98A16E4F51B54CA3ED8E1FC66C Ref B: SJCEDGE0408 Ref C: 2020-08-21T19:33:30Z
< set-cookie: _EDGE_S=F=1&SID=183E6ED6757362F805A561FB74C3637A; path=/; httponly; domain=bing.com
< set-cookie: _EDGE_V=1; path=/; httponly; expires=Wed, 15-Sep-2021 19:33:30 GMT; domain=bing.com
< set-cookie: MUID=1EB64EF3D80B6F7A2DE541DED9BB6E2F; samesite=none; path=/; secure; expires=Wed, 15-Sep-2021 19:33:30 GMT; domain=bing.com
< set-cookie: MUIDB=1EB64EF3D80B6F7A2DE541DED9BB6E2F; path=/; httponly; expires=Wed, 15-Sep-2021 19:33:30 GMT
< date: Fri, 21 Aug 2020 19:33:30 GMT
<
{ [193 bytes data]
* Curl_http_done: called premature == 0
100 193 100 193 0 0 2359 0 --:--:-- --:--:-- --:--:-- 2382
* Connection #0 to host bing.com left intact
<html><head><title>Object moved</title></head><body>
<h2>Object moved to <a href="https://www.bing.com:443/?toWww=1&redig=1FC8450CDBF44B4E8EE2E9B68674DD24">here</a>.</h2>
</body></html>
*****
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Trying 204.79.197.200...
* TCP_NODELAY set
* Connected to bing.com (204.79.197.200) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
* CAfile: /etc/ssl/certs/ca-certificates.crt
CApath: /etc/ssl/certs
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
} [5 bytes data]
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* Unknown SSL protocol error in connection to bing.com:443
* Curl_http_done: called premature == 1
* stopped the pause stream!
0 0 0 0 0 0 0 0 --:--:-- 0:00:01 --:--:-- 0
* Closing connection 0
curl: (35) Unknown SSL protocol error in connection to bing.com:443
while :; do echo ***** >> out_2 curl -vvv https://bing.com/ >> out_2 2>&1 ret=0; if [ 35 -ne 0 ]; thenwhile :; do echo ***** >> out_2 curl -vvv https://bing.com/ >> out_2 2>&1 ret=0; if [ 35 -ne 0 ]; thenwhile :; do echo ***** >> out_2 curl -vvv https://bing.com/ >> out_2 2>&1 ret=0; if [ 35 -ne 0 ]; then
Taking a look at the proxy logs to see if there's anything interesting.
hawkw
on 21 Aug 2020
With the log filter set to warn,linkerd=trace,rustls=trace,tokio-rustls=trace,hyper=trace, and kubectl logs piped into grep outbound to skip the admin logs from health checks, I get this output (including the last two successful requests):
[ 453.54325703s] TRACE outbound: linkerd2_proxy_transport::listen: accepted peer.addr=10.42.0.38:54328 orig.addr=Some(V4(204.79.197.200:443))
[ 453.54337956s] DEBUG outbound:accept{peer.addr=10.42.0.38:54328}: linkerd2_proxy_transport::tls::accept: skipping TLS reason=loopback
[ 453.57708318s] TRACE outbound:accept{peer.addr=10.42.0.38:54328}: linkerd2_app_core::proxy::server: did not detect protocol; forwarding TCP
[ 453.57720521s] DEBUG outbound:accept{peer.addr=10.42.0.38:54328}: linkerd2_app_outbound::prevent_loop: addr=204.79.197.200:443 self.port=4140
[ 453.57725400s] DEBUG outbound:accept{peer.addr=10.42.0.38:54328}: linkerd2_proxy_transport::tls::client: peer.identity=None(NoPeerName(NotHttp))
[ 453.57728757s] DEBUG outbound:accept{peer.addr=10.42.0.38:54328}: linkerd2_proxy_transport::connect: Connecting peer.addr=204.79.197.200:443
[ 453.65986439s] DEBUG outbound: linkerd2_proxy_transport::connect: Connected local.addr=10.42.0.38:54330 keepalive=Some(10s)
[ 453.65994484s] TRACE outbound: linkerd2_proxy_transport::tls::client: skipping TLS reason=not_http
[ 453.65996789s] DEBUG outbound: linkerd2_proxy_transport::metrics: client connection open
[ 453.66000666s] TRACE outbound: linkerd2_duplex: poll
[ 453.66002349s] TRACE outbound: linkerd2_duplex: reading
[ 453.66004443s] TRACE outbound: linkerd2_duplex: read 517B
[ 453.66006016s] TRACE outbound: linkerd2_duplex: writing 517B
[ 453.66029020s] TRACE outbound: linkerd2_duplex: wrote 517B
[ 453.66031935s] TRACE outbound: linkerd2_duplex: reading
[ 453.66035101s] TRACE outbound: linkerd2_duplex: reading
[ 453.79788684s] TRACE outbound: linkerd2_duplex: poll
[ 453.79795046s] TRACE outbound: linkerd2_duplex: reading
[ 453.79797471s] TRACE outbound: linkerd2_duplex: reading
[ 453.79822739s] TRACE outbound: linkerd2_duplex: read 2820B
[ 453.79829432s] TRACE outbound: linkerd2_duplex: writing 2820B
[ 453.79848367s] TRACE outbound: linkerd2_duplex: wrote 2820B
[ 453.79851012s] TRACE outbound: linkerd2_duplex: reading
[ 453.79855060s] TRACE outbound: linkerd2_duplex: read 2703B
[ 453.79857284s] TRACE outbound: linkerd2_duplex: writing 2703B
[ 453.79864778s] TRACE outbound: linkerd2_duplex: wrote 2703B
[ 453.79866922s] TRACE outbound: linkerd2_duplex: reading
[ 453.82590612s] TRACE outbound: linkerd2_duplex: poll
[ 453.82593628s] TRACE outbound: linkerd2_duplex: reading
[ 453.82596593s] TRACE outbound: linkerd2_duplex: read 158B
[ 453.82598327s] TRACE outbound: linkerd2_duplex: writing 158B
[ 453.82615289s] TRACE outbound: linkerd2_duplex: wrote 158B
[ 453.82618214s] TRACE outbound: linkerd2_duplex: reading
[ 453.82620529s] TRACE outbound: linkerd2_duplex: reading
[ 453.90383876s] TRACE outbound: linkerd2_duplex: poll
[ 453.90387002s] TRACE outbound: linkerd2_duplex: reading
[ 453.90388575s] TRACE outbound: linkerd2_duplex: reading
[ 453.90390919s] TRACE outbound: linkerd2_duplex: read 120B
[ 453.90392763s] TRACE outbound: linkerd2_duplex: writing 120B
[ 453.90405507s] TRACE outbound: linkerd2_duplex: wrote 120B
[ 453.90407941s] TRACE outbound: linkerd2_duplex: reading
[ 453.90599614s] TRACE outbound: linkerd2_duplex: poll
[ 453.90601948s] TRACE outbound: linkerd2_duplex: reading
[ 453.90604904s] TRACE outbound: linkerd2_duplex: read 103B
[ 453.90607639s] TRACE outbound: linkerd2_duplex: writing 103B
[ 453.90625563s] TRACE outbound: linkerd2_duplex: wrote 103B
[ 453.90628218s] TRACE outbound: linkerd2_duplex: reading
[ 453.90630322s] TRACE outbound: linkerd2_duplex: read 42B
[ 453.90631704s] TRACE outbound: linkerd2_duplex: writing 42B
[ 453.90642124s] TRACE outbound: linkerd2_duplex: wrote 42B
[ 453.90646172s] TRACE outbound: linkerd2_duplex: reading
[ 453.90649097s] TRACE outbound: linkerd2_duplex: read 64B
[ 453.90651011s] TRACE outbound: linkerd2_duplex: writing 64B
[ 453.90664577s] TRACE outbound: linkerd2_duplex: wrote 64B
[ 453.90667552s] TRACE outbound: linkerd2_duplex: reading
[ 453.90670899s] TRACE outbound: linkerd2_duplex: reading
[ 453.90733146s] TRACE outbound: linkerd2_duplex: poll
[ 453.90736563s] TRACE outbound: linkerd2_duplex: reading
[ 453.90739478s] TRACE outbound: linkerd2_duplex: read 38B
[ 453.90741412s] TRACE outbound: linkerd2_duplex: writing 38B
[ 453.90758574s] TRACE outbound: linkerd2_duplex: wrote 38B
[ 453.90761770s] TRACE outbound: linkerd2_duplex: reading
[ 453.90764736s] TRACE outbound: linkerd2_duplex: reading
[ 453.97712412s] TRACE outbound: linkerd2_duplex: poll
[ 453.97718463s] TRACE outbound: linkerd2_duplex: reading
[ 453.97721900s] TRACE outbound: linkerd2_duplex: reading
[ 453.97728081s] TRACE outbound: linkerd2_duplex: read 38B
[ 453.97729794s] TRACE outbound: linkerd2_duplex: writing 38B
[ 453.97745174s] TRACE outbound: linkerd2_duplex: wrote 38B
[ 453.97747698s] TRACE outbound: linkerd2_duplex: reading
[ 453.131759532s] TRACE outbound: linkerd2_duplex: poll
[ 453.131771295s] TRACE outbound: linkerd2_duplex: reading
[ 453.131776555s] TRACE outbound: linkerd2_duplex: reading
[ 453.131780813s] TRACE outbound: linkerd2_duplex: read 808B
[ 453.131783748s] TRACE outbound: linkerd2_duplex: writing 808B
[ 453.131798676s] TRACE outbound: linkerd2_duplex: wrote 808B
[ 453.131801151s] TRACE outbound: linkerd2_duplex: reading
[ 453.131976934s] TRACE outbound: linkerd2_duplex: poll
[ 453.131979348s] TRACE outbound: linkerd2_duplex: reading
[ 453.131981743s] TRACE outbound: linkerd2_duplex: read 31B
[ 453.131983235s] TRACE outbound: linkerd2_duplex: writing 31B
[ 453.132001009s] TRACE outbound: linkerd2_duplex: wrote 31B
[ 453.132003694s] TRACE outbound: linkerd2_duplex: reading
[ 453.132006149s] TRACE outbound: linkerd2_duplex: reading
[ 453.132566498s] TRACE outbound: linkerd2_duplex: poll
[ 453.132569183s] TRACE outbound: linkerd2_duplex: reading
[ 453.132571067s] TRACE outbound: linkerd2_duplex: read 0B
[ 453.132572680s] TRACE outbound: linkerd2_duplex: eof
[ 453.132574383s] TRACE outbound: linkerd2_duplex: shutting down
[ 453.132587788s] TRACE outbound: linkerd2_duplex: reading
[ 453.139190181s] TRACE outbound: linkerd2_duplex: poll
[ 453.139198136s] TRACE outbound: linkerd2_duplex: already shutdown
[ 453.139200290s] TRACE outbound: linkerd2_duplex: reading
[ 453.139204508s] TRACE outbound: linkerd2_duplex: read 0B
[ 453.139207313s] TRACE outbound: linkerd2_duplex: eof
[ 453.139209447s] TRACE outbound: linkerd2_duplex: shutting down
[ 453.139244814s] DEBUG outbound: linkerd2_app_core::accept_error: Connection failed error=Transport endpoint is not connected (os error 107)
[ 453.140734440s] TRACE outbound: linkerd2_proxy_transport::listen: accepted peer.addr=10.42.0.38:39510 orig.addr=Some(V4(13.107.21.200:443))
[ 453.140748497s] DEBUG outbound:accept{peer.addr=10.42.0.38:39510}: linkerd2_proxy_transport::tls::accept: skipping TLS reason=loopback
[ 453.144148806s] TRACE outbound:accept{peer.addr=10.42.0.38:39510}: linkerd2_app_core::proxy::server: did not detect protocol; forwarding TCP
[ 453.144165367s] DEBUG outbound:accept{peer.addr=10.42.0.38:39510}: linkerd2_app_outbound::prevent_loop: addr=13.107.21.200:443 self.port=4140
[ 453.144173903s] DEBUG outbound:accept{peer.addr=10.42.0.38:39510}: linkerd2_proxy_transport::tls::client: peer.identity=None(NoPeerName(NotHttp))
[ 453.144180075s] DEBUG outbound:accept{peer.addr=10.42.0.38:39510}: linkerd2_proxy_transport::connect: Connecting peer.addr=13.107.21.200:443
[ 453.152761419s] DEBUG outbound: linkerd2_proxy_transport::connect: Connected local.addr=10.42.0.38:39512 keepalive=Some(10s)
[ 453.152772610s] TRACE outbound: linkerd2_proxy_transport::tls::client: skipping TLS reason=not_http
[ 453.152776448s] DEBUG outbound: linkerd2_proxy_transport::metrics: client connection open
[ 453.152782880s] TRACE outbound: linkerd2_duplex: poll
[ 453.152784814s] TRACE outbound: linkerd2_duplex: reading
[ 453.152787248s] TRACE outbound: linkerd2_duplex: read 517B
[ 453.152788981s] TRACE outbound: linkerd2_duplex: writing 517B
[ 453.152809881s] TRACE outbound: linkerd2_duplex: wrote 517B
[ 453.152812997s] TRACE outbound: linkerd2_duplex: reading
[ 453.152816363s] TRACE outbound: linkerd2_duplex: reading
[ 453.163409831s] TRACE outbound: linkerd2_duplex: poll
[ 453.163416524s] TRACE outbound: linkerd2_duplex: reading
[ 453.163420812s] TRACE outbound: linkerd2_duplex: reading
[ 453.163427946s] TRACE outbound: linkerd2_duplex: read 4096B
[ 453.163430100s] TRACE outbound: linkerd2_duplex: writing 4096B
[ 453.163452131s] TRACE outbound: linkerd2_duplex: wrote 4096B
[ 453.163455347s] TRACE outbound: linkerd2_duplex: reading
[ 453.163459004s] TRACE outbound: linkerd2_duplex: read 1427B
[ 453.163460928s] TRACE outbound: linkerd2_duplex: writing 1427B
[ 453.163470706s] TRACE outbound: linkerd2_duplex: wrote 1427B
[ 453.163473462s] TRACE outbound: linkerd2_duplex: reading
[ 453.166279266s] TRACE outbound: linkerd2_duplex: poll
[ 453.166283344s] TRACE outbound: linkerd2_duplex: reading
[ 453.166286871s] TRACE outbound: linkerd2_duplex: read 158B
[ 453.166289065s] TRACE outbound: linkerd2_duplex: writing 158B
[ 453.166313120s] TRACE outbound: linkerd2_duplex: wrote 158B
[ 453.166316968s] TRACE outbound: linkerd2_duplex: reading
[ 453.166320444s] TRACE outbound: linkerd2_duplex: reading
[ 453.175577556s] TRACE outbound: linkerd2_duplex: poll
[ 453.175583888s] TRACE outbound: linkerd2_duplex: reading
[ 453.175586173s] TRACE outbound: linkerd2_duplex: reading
[ 453.175589469s] TRACE outbound: linkerd2_duplex: read 120B
[ 453.175591132s] TRACE outbound: linkerd2_duplex: writing 120B
[ 453.175606932s] TRACE outbound: linkerd2_duplex: wrote 120B
[ 453.175609477s] TRACE outbound: linkerd2_duplex: reading
[ 453.175812501s] TRACE outbound: linkerd2_duplex: poll
[ 453.175815105s] TRACE outbound: linkerd2_duplex: reading
[ 453.175817971s] TRACE outbound: linkerd2_duplex: read 103B
[ 453.175819474s] TRACE outbound: linkerd2_duplex: writing 103B
[ 453.175839321s] TRACE outbound: linkerd2_duplex: wrote 103B
[ 453.175842187s] TRACE outbound: linkerd2_duplex: reading
[ 453.175844471s] TRACE outbound: linkerd2_duplex: read 42B
[ 453.175846274s] TRACE outbound: linkerd2_duplex: writing 42B
[ 453.175858427s] TRACE outbound: linkerd2_duplex: wrote 42B
[ 453.175860882s] TRACE outbound: linkerd2_duplex: reading
[ 453.175862966s] TRACE outbound: linkerd2_duplex: read 64B
[ 453.175864489s] TRACE outbound: linkerd2_duplex: writing 64B
[ 453.175876361s] TRACE outbound: linkerd2_duplex: wrote 64B
[ 453.175878896s] TRACE outbound: linkerd2_duplex: reading
[ 453.175881331s] TRACE outbound: linkerd2_duplex: reading
[ 453.175918581s] TRACE outbound: linkerd2_duplex: poll
[ 453.175921166s] TRACE outbound: linkerd2_duplex: reading
[ 453.175923400s] TRACE outbound: linkerd2_duplex: read 38B
[ 453.175924923s] TRACE outbound: linkerd2_duplex: writing 38B
[ 453.175938198s] TRACE outbound: linkerd2_duplex: wrote 38B
[ 453.175940623s] TRACE outbound: linkerd2_duplex: reading
[ 453.175943268s] TRACE outbound: linkerd2_duplex: reading
[ 453.183407009s] TRACE outbound: linkerd2_duplex: poll
[ 453.183413551s] TRACE outbound: linkerd2_duplex: reading
[ 453.183417779s] TRACE outbound: linkerd2_duplex: reading
[ 453.183424913s] TRACE outbound: linkerd2_duplex: read 38B
[ 453.183427057s] TRACE outbound: linkerd2_duplex: writing 38B
[ 453.183444971s] TRACE outbound: linkerd2_duplex: wrote 38B
[ 453.183447957s] TRACE outbound: linkerd2_duplex: reading
[ 453.218011403s] TRACE outbound: linkerd2_duplex: poll
[ 453.218020029s] TRACE outbound: linkerd2_duplex: reading
[ 453.218024528s] TRACE outbound: linkerd2_duplex: reading
[ 453.218032733s] TRACE outbound: linkerd2_duplex: read 812B
[ 453.218035138s] TRACE outbound: linkerd2_duplex: writing 812B
[ 453.218056528s] TRACE outbound: linkerd2_duplex: wrote 812B
[ 453.218059694s] TRACE outbound: linkerd2_duplex: reading
[ 453.218286253s] TRACE outbound: linkerd2_duplex: poll
[ 453.218289609s] TRACE outbound: linkerd2_duplex: reading
[ 453.218292394s] TRACE outbound: linkerd2_duplex: read 31B
[ 453.218294248s] TRACE outbound: linkerd2_duplex: writing 31B
[ 453.218318995s] TRACE outbound: linkerd2_duplex: wrote 31B
[ 453.218322321s] TRACE outbound: linkerd2_duplex: reading
[ 453.218325267s] TRACE outbound: linkerd2_duplex: reading
[ 453.218956720s] TRACE outbound: linkerd2_duplex: poll
[ 453.218959566s] TRACE outbound: linkerd2_duplex: reading
[ 453.218961459s] TRACE outbound: linkerd2_duplex: read 0B
[ 453.218963133s] TRACE outbound: linkerd2_duplex: eof
[ 453.218965437s] TRACE outbound: linkerd2_duplex: shutting down
[ 453.218980175s] TRACE outbound: linkerd2_duplex: reading
[ 453.227119203s] TRACE outbound: linkerd2_proxy_transport::listen: accepted peer.addr=10.42.0.38:54336 orig.addr=Some(V4(204.79.197.200:443))
[ 453.227138199s] DEBUG outbound:accept{peer.addr=10.42.0.38:54336}: linkerd2_proxy_transport::tls::accept: skipping TLS reason=loopback
[ 453.230531174s] TRACE outbound:accept{peer.addr=10.42.0.38:54336}: linkerd2_app_core::proxy::server: did not detect protocol; forwarding TCP
[ 453.230547855s] DEBUG outbound:accept{peer.addr=10.42.0.38:54336}: linkerd2_app_outbound::prevent_loop: addr=204.79.197.200:443 self.port=4140
[ 453.230556291s] DEBUG outbound:accept{peer.addr=10.42.0.38:54336}: linkerd2_proxy_transport::tls::client: peer.identity=None(NoPeerName(NotHttp))
[ 453.230560880s] DEBUG outbound:accept{peer.addr=10.42.0.38:54336}: linkerd2_proxy_transport::connect: Connecting peer.addr=204.79.197.200:443
[ 453.239396815s] TRACE outbound: linkerd2_duplex: poll
[ 453.239403618s] TRACE outbound: linkerd2_duplex: already shutdown
[ 453.239405922s] TRACE outbound: linkerd2_duplex: reading
[ 453.239410130s] TRACE outbound: linkerd2_duplex: read 0B
[ 453.239412334s] TRACE outbound: linkerd2_duplex: eof
[ 453.239414579s] TRACE outbound: linkerd2_duplex: shutting down
[ 453.239447040s] DEBUG outbound: linkerd2_app_core::accept_error: Connection failed error=Transport endpoint is not connected (os error 107)
[ 454.231584952s] DEBUG outbound: linkerd2_app_core::accept_error: Connection failed error=request timed out
So it looks like the proxy (correctly) treats all these requests as raw TCP connections, since the client-hello doesn't match its SNI name. For the last request, the one that fails, it looks like the proxy tries to establish the outbound connection, but once it is established, it immediately closes, presumably because the upstream server didn't like the client handshake. There's not a lot of detail here about _why_ the client hello may have been messed up, so I'll do some more digging.
hawkw
on 21 Aug 2020
After adding significantly more verbose debug logging, it looks like the proxy is hitting the 1 second default outbound connection timeout while trying to open a TCP connection to the destination:
[ 396.611186563s] TRACE ThreadId(22) outbound: linkerd2_proxy_transport::listen: Accepted peer.addr=10.42.0.77:47744 orig.addr=Some(V4(204.79.197.200:443))
[ 396.611194598s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: new
[ 396.611198104s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: enter
[ 396.611200519s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: exit
[ 396.611212621s] INFO ThreadId(22) outbound: linkerd2_app: exit
[ 396.611216268s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: enter
[ 396.611222279s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_stack_tracing: poll_ready
[ 396.611224974s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_stack_tracing: ready=true
[ 396.611227288s] DEBUG ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_outbound::prevent_loop: addr=204.79.197.200:443 self.port=4140
[ 396.611231075s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_stack_tracing: make_service target=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }
[ 396.611236325s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: new
[ 396.611239291s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 396.611241535s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 396.611244811s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 396.611246765s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: making
[ 396.611249329s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: ready=true
[ 396.611251573s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 396.611254689s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_stack_tracing: new_service target=Addrs { local: V4(10.42.0.77:47744), peer: V4(10.42.0.77:47744), orig_dst: Some(V4(204.79.197.200:443)) }
[ 396.611259468s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: new
[ 396.611261592s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: enter
[ 396.611265539s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: exit
[ 396.611280247s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_io::peek: poll_peek=Pending
[ 396.611283473s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: exit
[ 396.614659000s] INFO ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: enter
[ 396.614665702s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_io::peek: poll_peek=Ready(Ok(517))
[ 396.614667866s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_io::peek: peeked.len=517
[ 396.614672815s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_proxy_http::detect: Forwarding TCP
[ 396.614676101s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 396.614678205s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: poll ready
[ 396.614680760s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: ready=true
[ 396.614683114s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 396.614686100s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 396.614727707s] DEBUG ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_proxy_transport::tls::client: peer.identity=None(NotHttp)
[ 396.614731173s] DEBUG ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_proxy_transport::connect: Connecting peer.addr=204.79.197.200:443
[ 396.614738848s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 396.614741963s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 396.614744107s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_proxy_tcp::forward: in accept future!
[ 396.614747514s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: new
[ 396.614750629s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: enter
[ 396.614794962s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: exit
[ 396.614799139s] TRACE ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 396.614801474s] INFO ThreadId(12) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: exit
[ 397.615812870s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: enter
[ 397.615833558s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 397.615837696s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: enter
[ 397.615983306s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: exit
[ 397.615990138s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: close time.busy=190µs time.idle=1.00s
[ 397.616063725s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 397.616091406s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: close time.busy=356µs time.idle=1.00s
[ 397.616113146s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: close time.busy=3.94µs time.idle=1.00s
[ 397.616122173s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: Connection closed error=request timed out
[ 397.616173729s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: exit
[ 397.616175502s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.77:47744}: linkerd2_app_core::serve: close time.busy=574µs time.idle=1.00s
increased the value of LINKERD2_PROXY_OUTBOUND_CONNECT_TIMEOUT to two minutes, and it _still_ eventuallyh hits the timeout:
[ 497.251011666s] INFO ThreadId(23) outbound: linkerd2_app: enter
[ 497.251026103s] TRACE ThreadId(23) outbound: linkerd2_proxy_transport::listen: Accepted peer.addr=10.42.0.78:52996 orig.addr=Some(V4(204.79.197.200:443))
[ 497.251033456s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: new
[ 497.251036111s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: enter
[ 497.251039508s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: exit
[ 497.251049937s] INFO ThreadId(23) outbound: linkerd2_app: exit
[ 497.251053754s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: enter
[ 497.251059234s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_stack_tracing: poll_ready
[ 497.251061899s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_stack_tracing: ready=true
[ 497.251064143s] DEBUG ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_outbound::prevent_loop: addr=204.79.197.200:443 self.port=4140
[ 497.251067780s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_stack_tracing: make_service target=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }
[ 497.251074172s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: new
[ 497.251077859s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 497.251080694s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 497.251084421s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 497.251087787s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: making
[ 497.251090182s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: ready=true
[ 497.251094089s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 497.251096874s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_stack_tracing: new_service target=Addrs { local: V4(10.42.0.78:52996), peer: V4(10.42.0.78:52996), orig_dst: Some(V4(204.79.197.200:443)) }
[ 497.251103075s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: new
[ 497.251105680s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: enter
[ 497.251110299s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: exit
[ 497.251124215s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_io::peek: poll_peek=Pending
[ 497.251128182s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: exit
[ 497.254371843s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: enter
[ 497.254376882s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_io::peek: poll_peek=Ready(Ok(517))
[ 497.254378585s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_io::peek: peeked.len=517
[ 497.254382513s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_proxy_http::detect: Forwarding TCP
[ 497.254385508s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 497.254387101s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: poll ready
[ 497.254389165s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: ready=true
[ 497.254391109s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 497.254393844s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 497.254422677s] DEBUG ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_proxy_transport::tls::client: peer.identity=None(NotHttp)
[ 497.254428237s] DEBUG ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_proxy_transport::connect: Connecting peer.addr=204.79.197.200:443
[ 497.254433878s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 497.254436713s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 497.254438246s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_proxy_tcp::forward: in accept future!
[ 497.254441231s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: new
[ 497.254443946s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: enter
[ 497.254485784s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: exit
[ 497.254490613s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 497.254493358s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: exit
[ 617.255707107s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: enter
[ 617.255724025s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 617.255728144s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: enter
[ 617.255751666s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: exit
[ 617.255755244s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: close time.busy=65.2µs time.idle=120s
[ 617.255777814s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 617.255781041s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: close time.busy=166µs time.idle=120s
[ 617.255784930s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: close time.busy=4.60µs time.idle=120s
[ 617.255793268s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: Connection closed error=request timed out
[ 617.255797046s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: exit
[ 617.255798830s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.78:52996}: linkerd2_app_core::serve: close time.busy=291µs time.idle=120s
fascinating!
hawkw
on 25 Aug 2020
It's like reading a Stephen King novel!
Parad0X
on 25 Aug 2020
😄1
ran the repro again with the debug container. here's tshark output from what i'm pretty sure is the last request (everything following involves only IPs in the cluster and is basically just metrics scrapes and readiness probes):
453595 599.913450304 10.42.0.80 → 10.43.0.10 DNS 96 Standard query 0xda9b A bing.com.default.svc.cluster.local
453596 599.913481945 10.42.0.80 → 10.43.0.10 DNS 96 Standard query 0x242e AAAA bing.com.default.svc.cluster.local
453597 599.913596244 10.43.0.10 → 10.42.0.80 DNS 189 Standard query response 0x242e No such name AAAA bing.com.default.svc.cluster.local SOA ns.dns.cluster.local
453598 599.913623656 10.43.0.10 → 10.42.0.80 DNS 189 Standard query response 0xda9b No such name A bing.com.default.svc.cluster.local SOA ns.dns.cluster.local
453599 599.913656499 10.42.0.80 → 10.43.0.10 DNS 88 Standard query 0xf058 A bing.com.svc.cluster.local
453600 599.913675015 10.42.0.80 → 10.43.0.10 DNS 88 Standard query 0x448a AAAA bing.com.svc.cluster.local
453601 599.913774115 10.43.0.10 → 10.42.0.80 DNS 181 Standard query response 0x448a No such name AAAA bing.com.svc.cluster.local SOA ns.dns.cluster.local
453602 599.913801327 10.43.0.10 → 10.42.0.80 DNS 181 Standard query response 0xf058 No such name A bing.com.svc.cluster.local SOA ns.dns.cluster.local
453603 599.913840582 10.42.0.80 → 10.43.0.10 DNS 84 Standard query 0x482a A bing.com.cluster.local
453604 599.913859939 10.42.0.80 → 10.43.0.10 DNS 84 Standard query 0xd4d0 AAAA bing.com.cluster.local
453605 599.913897231 10.43.0.10 → 10.42.0.80 DNS 177 Standard query response 0xd4d0 No such name AAAA bing.com.cluster.local SOA ns.dns.cluster.local
453606 599.913928621 10.43.0.10 → 10.42.0.80 DNS 177 Standard query response 0x482a No such name A bing.com.cluster.local SOA ns.dns.cluster.local
453607 599.913947046 10.42.0.80 → 10.43.0.10 DNS 70 Standard query 0x4e86 A bing.com
453608 599.913953709 10.42.0.80 → 10.43.0.10 DNS 70 Standard query 0x0c3f AAAA bing.com
453609 599.913985730 10.43.0.10 → 10.42.0.80 DNS 106 Standard query response 0x0c3f AAAA bing.com AAAA 2620:1ec:c11::200
453610 599.914008274 10.43.0.10 → 10.42.0.80 DNS 118 Standard query response 0x4e86 A bing.com A 204.79.197.200 A 13.107.21.200
453611 599.914681975 13.107.21.200 → 10.42.0.80 TCP 56 443 → 54710 [ACK] Seq=6484 Ack=954 Win=4195584 Len=0
453612 599.915960446 13.107.21.200 → 10.42.0.80 TCP 56 443 → 54710 [ACK] Seq=6484 Ack=955 Win=4195584 Len=0
453613 599.916694243 13.107.21.200 → 10.42.0.80 TCP 56 443 → 54710 [FIN, ACK] Seq=6484 Ack=955 Win=4195584 Len=0
453614 599.916699773 10.42.0.80 → 13.107.21.200 TCP 56 54710 → 443 [ACK] Seq=955 Ack=6485 Win=64128 Len=0
453615 599.916771831 13.107.21.200 → 10.42.0.80 TCP 68 443 → 54708 [FIN, ACK] Seq=6484 Ack=955 Win=65536 Len=0 TSval=3303330677 TSecr=499769860
453616 599.916778163 10.42.0.80 → 127.0.0.1 TCP 68 54708 → 4140 [ACK] Seq=955 Ack=6485 Win=64256 Len=0 TSval=499769867 TSecr=3303330677
453617 599.917446755 10.42.0.80 → 127.0.0.1 TCP 76 38018 → 4140 [SYN] Seq=0 Win=64860 Len=0 MSS=1410 SACK_PERM=1 TSval=3906382478 TSecr=0 WS=128
453618 599.917455281 204.79.197.200 → 10.42.0.80 TCP 76 443 → 38018 [SYN, ACK] Seq=0 Ack=1 Win=65483 Len=0 MSS=65495 SACK_PERM=1 TSval=3303330678 TSecr=3906382478 WS=128
453619 599.917462545 10.42.0.80 → 127.0.0.1 TCP 68 38018 → 4140 [ACK] Seq=1 Ack=1 Win=64896 Len=0 TSval=3906382478 TSecr=3303330678
453620 599.921134003 10.42.0.80 → 127.0.0.1 TLSv1 585 Client Hello
453621 599.921141307 204.79.197.200 → 10.42.0.80 TCP 68 443 → 38018 [ACK] Seq=1 Ack=518 Win=65024 Len=0 TSval=3303330682 TSecr=3906382482
453622 599.921281616 10.42.0.80 → 204.79.197.200 TCP 76 38020 → 443 [SYN] Seq=0 Win=64860 Len=0 MSS=1410 SACK_PERM=1 TSval=3906382482 TSecr=0 WS=128
453623 600.922388620 204.79.197.200 → 10.42.0.80 TCP 68 443 → 38018 [FIN, ACK] Seq=1 Ack=518 Win=65536 Len=0 TSval=3303331683 TSecr=3906382482
453624 600.922983941 10.42.0.80 → 127.0.0.1 TCP 68 38018 → 4140 [ACK] Seq=518 Ack=2 Win=64896 Len=0 TSval=3906383484 TSecr=3303331683
453625 600.923138687 10.42.0.80 → 127.0.0.1 TCP 68 38018 → 4140 [FIN, ACK] Seq=518 Ack=2 Win=64896 Len=0 TSval=3906383484 TSecr=3303331683
453626 600.923143797 204.79.197.200 → 10.42.0.80 TCP 68 443 → 38018 [ACK] Seq=2 Ack=519 Win=65536 Len=0 TSval=3303331684 TSecr=3906383484
and the proxy's logs:
[ 603.425483160s] TRACE ThreadId(22) outbound: linkerd2_proxy_transport::listen: Accepted peer.addr=10.42.0.80:38018 orig.addr=Some(V4(204.79.197.200:443))
[ 603.425494853s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: new
[ 603.425498389s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: enter
[ 603.425501085s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: exit
[ 603.425516514s] INFO ThreadId(22) outbound: linkerd2_app: exit
[ 603.425519831s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: enter
[ 603.425529880s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_stack_tracing: poll_ready
[ 603.425532926s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_stack_tracing: ready=true
[ 603.425535841s] DEBUG ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_outbound::prevent_loop: addr=204.79.197.200:443 self.port=4140
[ 603.425540310s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_stack_tracing: make_service target=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }
[ 603.425548065s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: new
[ 603.425551541s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 603.425554337s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 603.425558004s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 603.425560248s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: making
[ 603.425563645s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: ready=true
[ 603.425566450s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 603.425571049s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_stack_tracing: new_service target=Addrs { local: V4(10.42.0.80:38018), peer: V4(10.42.0.80:38018), orig_dst: Some(V4(204.79.197.200:443)) }
[ 603.425577301s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: new
[ 603.425580898s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: enter
[ 603.425585015s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: exit
[ 603.425601207s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_io::peek: poll_peek=Pending
[ 603.425604733s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: exit
[ 603.429123188s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: enter
[ 603.429132315s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_io::peek: poll_peek=Ready(Ok(517))
[ 603.429134750s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_io::peek: peeked.len=517
[ 603.429141643s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_proxy_http::detect: Forwarding TCP
[ 603.429145150s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 603.429147083s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: poll ready
[ 603.429149919s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: ready=true
[ 603.429152394s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 603.429155119s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 603.429195817s] DEBUG ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_proxy_transport::tls::client: peer.identity=None(NotHttp)
[ 603.429200766s] DEBUG ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_proxy_transport::connect: Connecting peer.addr=204.79.197.200:443
[ 603.429208281s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 603.429211427s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 603.429213410s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_proxy_tcp::forward: in accept future!
[ 603.429217839s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: new
[ 603.429220825s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: enter
[ 603.429310817s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: exit
[ 603.429315065s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 603.429317189s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: exit
[ 604.430294184s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: enter
[ 604.430311958s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 604.430316467s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: enter
[ 604.430341625s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: exit
[ 604.430346344s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: close time.busy=115µs time.idle=1.00s
[ 604.430379658s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 604.430383585s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:tcp_forward{endpoint=TcpEndpoint { addr: V4(204.79.197.200:443), identity: None(NotHttp) }}: linkerd2_app_outbound: close time.busy=243µs time.idle=1.00s
[ 604.430387974s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}:source{target.addr=204.79.197.200:443}: linkerd2_app_outbound: close time.busy=4.12µs time.idle=1.00s
[ 604.430398243s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: Connection closed error=request timed out
[ 604.430402441s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: exit
[ 604.430404385s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:38018}: linkerd2_app_core::serve: close time.busy=391µs time.idle=1.00s
This is pretty strange because the tshark capture looks pretty different from what @KIVagant posted above --- in the bad capture, there is a successful handshake and key exchange with the server:
349318 1858.308900911 10.56.43.237 → 93.184.216.34 TLSv1 170 Client Hello
349319 1858.310116791 93.184.216.34 → 10.56.43.237 TCP 68 443 → 51048 [ACK] Seq=1 Ack=103 Win=65536 Len=0 TSval=2742442734 TSecr=1099592033
349320 1858.311080839 93.184.216.34 → 10.56.43.237 TLSv1 4164 Server Hello, Certificate
349321 1858.311105282 10.56.43.237 → 93.184.216.34 TCP 68 51048 → 443 [ACK] Seq=103 Ack=4097 Win=45056 Len=0 TSval=1099592035 TSecr=2742442735
349322 1858.311085527 93.184.216.34 → 10.56.43.237 TLSv1 395 Server Key Exchange, Server Hello Done
349323 1858.311110119 10.56.43.237 → 93.184.216.34 TCP 68 51048 → 443 [ACK] Seq=103 Ack=4424 Win=48128 Len=0 TSval=1099592035 TSecr=2742442735
349324 1858.311166352 93.184.216.34 → 10.56.43.237 TLSv1 4164 Server Hello, Certificate
349325 1858.311186214 10.56.43.237 → 127.0.0.1 TCP 68 51046 → 4140 [ACK] Seq=103 Ack=4097 Win=45056 Len=0 TSval=1099592035 TSecr=3444165823
349326 1858.311206289 93.184.216.34 → 10.56.43.237 TLSv1 395 Server Key Exchange, Server Hello Done
349327 1858.311212959 10.56.43.237 → 127.0.0.1 TCP 68 51046 → 4140 [ACK] Seq=103 Ack=4424 Win=53248 Len=0 TSval=1099592035 TSecr=3444165823
349328 1858.313958194 10.56.43.237 → 127.0.0.1 TLSv1 206 Client Key Exchange, Change Cipher Spec, Encrypted Handshake Message
349329 1858.314028909 10.56.43.237 → 93.184.216.34 TLSv1 206 Client Key Exchange, Change Cipher Spec, Encrypted Handshake Message
we establish a session
349330 1858.315509019 93.184.216.34 → 10.56.43.237 TLSv1 306 New Session Ticket, Change Cipher Spec, Encrypted Handshake Message
349331 1858.315568848 93.184.216.34 → 10.56.43.237 TLSv1 306 New Session Ticket, Change Cipher Spec, Encrypted Handshake Message
349332 1858.315923692 10.56.43.237 → 127.0.0.1 TLSv1 150 Application Data, Application Data
then the client sends an alert...
349333 1858.315983576 10.56.43.237 → 127.0.0.1 TLSv1 109 Encrypted Alert
349334 1858.315990724 10.56.43.237 → 93.184.216.34 TLSv1 150 Application Data, Application Data
349335 1858.316017780 93.184.216.34 → 10.56.43.237 TCP 68 443 → 51046 [ACK] Seq=4662 Ack=365 Win=45056 Len=0 TSval=3444165828 TSecr=1099592040
349336 1858.316037288 10.56.43.237 → 93.184.216.34 TLSv1 109 Encrypted Alert
...and we tear down the conn:
349337 1858.316057102 10.56.43.237 → 93.184.216.34 TCP 68 51048 → 443 [FIN, ACK] Seq=364 Ack=4662 Win=50688 Len=0 TSval=1099592040 TSecr=2742442740
349338 1858.317263160 93.184.216.34 → 10.56.43.237 TLSv1 760 Application Data, Application Data, Application Data, Application Data
349339 1858.317316674 93.184.216.34 → 10.56.43.237 TLSv1 109 Encrypted Alert
349340 1858.317331265 93.184.216.34 → 10.56.43.237 TLSv1 760 Application Data, Application Data, Application Data, Application Data
349341 1858.317323785 93.184.216.34 → 10.56.43.237 TCP 68 443 → 51048 [FIN, ACK] Seq=5395 Ack=365 Win=67072 Len=0 TSval=2742442742 TSecr=1099592040
349342 1858.317345121 10.56.43.237 → 93.184.216.34 TCP 68 51048 → 443 [ACK] Seq=365 Ack=5396 Win=53760 Len=0 TSval=1099592041 TSecr=2742442742
349343 1858.317345962 10.56.43.237 → 127.0.0.1 TCP 56 51046 → 4140 [RST] Seq=365 Win=0 Len=0
This is _not_ what happens in my capture: we just never hear back from the upstream server, and tear down the connection upon hitting the timeout. It's possible that I'm hitting something unrelated, or am just failing to actually reproduce this issue...
hawkw
on 25 Aug 2020
Hmm, the results with openssl/example.com is very different than curl/bing.
Proxy log
[ 3205.754274463s] TRACE ThreadId(23) outbound: linkerd2_proxy_transport::listen: Accepted peer.addr=10.42.0.80:44804 orig.addr=Some(V4(93.184.216.34:443))
[ 3205.754282057s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: new
[ 3205.754284432s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: enter
[ 3205.754287798s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: exit
[ 3205.754300231s] INFO ThreadId(23) outbound: linkerd2_app: exit
[ 3205.754303246s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: enter
[ 3205.754308997s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_stack_tracing: poll_ready
[ 3205.754311952s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_stack_tracing: ready=true
[ 3205.754313976s] DEBUG ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_outbound::prevent_loop: addr=93.184.216.34:443 self.port=4140
[ 3205.754316340s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_stack_tracing: make_service target=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }
[ 3205.754321049s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: new
[ 3205.754323263s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.754326128s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.754328262s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.754329785s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: making
[ 3205.754331648s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: ready=true
[ 3205.754334934s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.754337830s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_stack_tracing: new_service target=Addrs { local: V4(10.42.0.80:44804), peer: V4(10.42.0.80:44804), orig_dst: Some(V4(93.184.216.34:443)) }
[ 3205.754342238s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:source{target.addr=93.184.216.34:443}: linkerd2_app_outbound: new
[ 3205.754343921s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:source{target.addr=93.184.216.34:443}: linkerd2_app_outbound: enter
[ 3205.754346496s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:source{target.addr=93.184.216.34:443}: linkerd2_app_outbound: exit
[ 3205.754360612s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_io::peek: poll_peek=Ready(Ok(102))
[ 3205.754363357s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_io::peek: peeked.len=102
[ 3205.754367084s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_proxy_http::detect: Forwarding TCP
[ 3205.754369198s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.754371382s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: poll ready
[ 3205.754372944s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: ready=true
[ 3205.754374708s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.754376471s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.754403431s] DEBUG ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_proxy_transport::tls::client: peer.identity=None(NotHttp)
[ 3205.754406035s] DEBUG ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_proxy_transport::connect: Connecting peer.addr=93.184.216.34:443
[ 3205.754410754s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.754413449s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.754415202s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_proxy_tcp::forward: in accept future!
[ 3205.754418348s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: new
[ 3205.754421063s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: enter
[ 3205.754471045s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: exit
[ 3205.754474732s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.754476906s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: exit
[ 3205.759538134s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}: linkerd2_app_core::serve: enter
[ 3205.759548122s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.759552049s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: poll
[ 3205.759555375s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: already shutdown
[ 3205.759558732s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: reading
[ 3205.759560946s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:dst: linkerd2_proxy_tcp::forward: enter
[ 3205.759566716s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:dst: linkerd2_io::instrumented: poll_read_buf=Ready(Ok(733))
[ 3205.759572036s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:dst: linkerd2_proxy_tcp::forward: exit
[ 3205.759575943s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: read 733B
[ 3205.759579309s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: writing 733B
[ 3205.759581584s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:src: linkerd2_proxy_tcp::forward: enter
[ 3205.759605307s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:src: linkerd2_io::instrumented: poll_write_buf=Ready(Ok(733))
[ 3205.759609054s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:src: linkerd2_proxy_tcp::forward: exit
[ 3205.759611198s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: wrote 733B
[ 3205.759613823s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: reading
[ 3205.759615997s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:dst: linkerd2_proxy_tcp::forward: enter
[ 3205.759620175s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:dst: linkerd2_io::instrumented: poll_read_buf=Pending
[ 3205.759623090s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:dst: linkerd2_proxy_tcp::forward: exit
[ 3205.759625444s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.759629051s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}: linkerd2_app_core::serve: exit
[ 3205.759767356s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}: linkerd2_app_core::serve: enter
[ 3205.759771914s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.759774088s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: poll
[ 3205.759776583s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: already shutdown
[ 3205.759779438s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: reading
[ 3205.759781642s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:dst: linkerd2_proxy_tcp::forward: enter
[ 3205.759785319s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:dst: linkerd2_io::instrumented: poll_read_buf=Ready(Ok(0))
[ 3205.759788805s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:dst: linkerd2_proxy_tcp::forward: exit
[ 3205.759790909s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: read 0B
[ 3205.759792772s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: eof
[ 3205.759795037s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_duplex: shutting down
[ 3205.759798683s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:src: linkerd2_proxy_tcp::forward: enter
[ 3205.759803412s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:src: linkerd2_io::instrumented: poll_shutdown=Ready(Err(Os { code: 107, kind: NotConnected, message: "Transport endpoint is not connected" }))
[ 3205.759812579s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:src: linkerd2_proxy_tcp::forward: exit
[ 3205.759822146s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:src: linkerd2_proxy_tcp::forward: close time.busy=452µs time.idle=28.5ms
OpenSSL client output (one good request prior to the failure)
:
*****
CONNECTED(00000003)
---
Certificate chain
0 s:/C=US/ST=California/L=Los Angeles/O=Internet Corporation for Assigned Names and Numbers/OU=Technology/CN=www.example.org
i:/C=US/O=DigiCert Inc/CN=DigiCert SHA2 Secure Server CA
1 s:/C=US/O=DigiCert Inc/CN=DigiCert SHA2 Secure Server CA
i:/C=US/O=DigiCert Inc/OU=www.digicert.com/CN=DigiCert Global Root CA
2 s:/C=US/O=DigiCert Inc/OU=www.digicert.com/CN=DigiCert Global Root CA
i:/C=US/O=DigiCert Inc/OU=www.digicert.com/CN=DigiCert Global Root CA
---
Server certificate
-----BEGIN CERTIFICATE-----
MIIHQDCCBiigAwIBAgIQD9B43Ujxor1NDyupa2A4/jANBgkqhkiG9w0BAQsFADBN
MQswCQYDVQQGEwJVUzEVMBMGA1UEChMMRGlnaUNlcnQgSW5jMScwJQYDVQQDEx5E
aWdpQ2VydCBTSEEyIFNlY3VyZSBTZXJ2ZXIgQ0EwHhcNMTgxMTI4MDAwMDAwWhcN
MjAxMjAyMTIwMDAwWjCBpTELMAkGA1UEBhMCVVMxEzARBgNVBAgTCkNhbGlmb3Ju
aWExFDASBgNVBAcTC0xvcyBBbmdlbGVzMTwwOgYDVQQKEzNJbnRlcm5ldCBDb3Jw
b3JhdGlvbiBmb3IgQXNzaWduZWQgTmFtZXMgYW5kIE51bWJlcnMxEzARBgNVBAsT
ClRlY2hub2xvZ3kxGDAWBgNVBAMTD3d3dy5leGFtcGxlLm9yZzCCASIwDQYJKoZI
hvcNAQEBBQADggEPADCCAQoCggEBANDwEnSgliByCGUZElpdStA6jGaPoCkrp9vV
rAzPpXGSFUIVsAeSdjF11yeOTVBqddF7U14nqu3rpGA68o5FGGtFM1yFEaogEv5g
rJ1MRY/d0w4+dw8JwoVlNMci+3QTuUKf9yH28JxEdG3J37Mfj2C3cREGkGNBnY80
eyRJRqzy8I0LSPTTkhr3okXuzOXXg38ugr1x3SgZWDNuEaE6oGpyYJIBWZ9jF3pJ
QnucP9vTBejMh374qvyd0QVQq3WxHrogy4nUbWw3gihMxT98wRD1oKVma1NTydvt
hcNtBfhkp8kO64/hxLHrLWgOFT/l4tz8IWQt7mkrBHjbd2XLVPkCAwEAAaOCA8Ew
ggO9MB8GA1UdIwQYMBaAFA+AYRyCMWHVLyjnjUY4tCzhxtniMB0GA1UdDgQWBBRm
mGIC4AmRp9njNvt2xrC/oW2nvjCBgQYDVR0RBHoweIIPd3d3LmV4YW1wbGUub3Jn
ggtleGFtcGxlLmNvbYILZXhhbXBsZS5lZHWCC2V4YW1wbGUubmV0ggtleGFtcGxl
Lm9yZ4IPd3d3LmV4YW1wbGUuY29tgg93d3cuZXhhbXBsZS5lZHWCD3d3dy5leGFt
cGxlLm5ldDAOBgNVHQ8BAf8EBAMCBaAwHQYDVR0lBBYwFAYIKwYBBQUHAwEGCCsG
AQUFBwMCMGsGA1UdHwRkMGIwL6AtoCuGKWh0dHA6Ly9jcmwzLmRpZ2ljZXJ0LmNv
bS9zc2NhLXNoYTItZzYuY3JsMC+gLaArhilodHRwOi8vY3JsNC5kaWdpY2VydC5j
b20vc3NjYS1zaGEyLWc2LmNybDBMBgNVHSAERTBDMDcGCWCGSAGG/WwBATAqMCgG
CCsGAQUFBwIBFhxodHRwczovL3d3dy5kaWdpY2VydC5jb20vQ1BTMAgGBmeBDAEC
AjB8BggrBgEFBQcBAQRwMG4wJAYIKwYBBQUHMAGGGGh0dHA6Ly9vY3NwLmRpZ2lj
ZXJ0LmNvbTBGBggrBgEFBQcwAoY6aHR0cDovL2NhY2VydHMuZGlnaWNlcnQuY29t
L0RpZ2lDZXJ0U0hBMlNlY3VyZVNlcnZlckNBLmNydDAMBgNVHRMBAf8EAjAAMIIB
fwYKKwYBBAHWeQIEAgSCAW8EggFrAWkAdwCkuQmQtBhYFIe7E6LMZ3AKPDWYBPkb
37jjd80OyA3cEAAAAWdcMZVGAAAEAwBIMEYCIQCEZIG3IR36Gkj1dq5L6EaGVycX
sHvpO7dKV0JsooTEbAIhALuTtf4wxGTkFkx8blhTV+7sf6pFT78ORo7+cP39jkJC
AHYAh3W/51l8+IxDmV+9827/Vo1HVjb/SrVgwbTq/16ggw8AAAFnXDGWFQAABAMA
RzBFAiBvqnfSHKeUwGMtLrOG3UGLQIoaL3+uZsGTX3MfSJNQEQIhANL5nUiGBR6g
l0QlCzzqzvorGXyB/yd7nttYttzo8EpOAHYAb1N2rDHwMRnYmQCkURX/dxUcEdkC
wQApBo2yCJo32RMAAAFnXDGWnAAABAMARzBFAiEA5Hn7Q4SOyqHkT+kDsHq7ku7z
RDuM7P4UDX2ft2Mpny0CIE13WtxJAUr0aASFYZ/XjSAMMfrB0/RxClvWVss9LHKM
MA0GCSqGSIb3DQEBCwUAA4IBAQBzcIXvQEGnakPVeJx7VUjmvGuZhrr7DQOLeP4R
8CmgDM1pFAvGBHiyzvCH1QGdxFl6cf7wbp7BoLCRLR/qPVXFMwUMzcE1GLBqaGZM
v1Yh2lvZSLmMNSGRXdx113pGLCInpm/TOhfrvr0TxRImc8BdozWJavsn1N2qdHQu
N+UBO6bQMLCD0KHEdSGFsuX6ZwAworxTg02/1qiDu7zW7RyzHvFYA4IAjpzvkPIa
X6KjBtpdvp/aXabmL95YgBjT8WJ7pqOfrqhpcmOBZa6Cg6O1l4qbIFH/Gj9hQB5I
0Gs4+eH6F9h3SojmPTYkT+8KuZ9w84Mn+M8qBXUQoYoKgIjN
-----END CERTIFICATE-----
subject=/C=US/ST=California/L=Los Angeles/O=Internet Corporation for Assigned Names and Numbers/OU=Technology/CN=www.example.org
issuer=/C=US/O=DigiCert Inc/CN=DigiCert SHA2 Secure Server CA
---
No client certificate CA names sent
Server Temp Key: ECDH, P-256, 256 bits
---
SSL handshake has read 4661 bytes and written 240 bytes
Verification: OK
---
New, TLSv1.0, Cipher is ECDHE-RSA-AES128-SHA
Server public key is 2048 bit
Secure Renegotiation IS supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
Protocol : TLSv1
Cipher : ECDHE-RSA-AES128-SHA
Session-ID: CE02D51EF65AB1A33B6DEFE25E72A7186B1C7446EC9F6A0199A76A07FA26657A
Session-ID-ctx:
Master-Key: 7F982E4E2A869F4239337CC91A1496A939484B6F8307C0EF0B9093A989134430C2CE93C5DA64E2C2A986228133A5690C
PSK identity: None
PSK identity hint: None
SRP username: None
TLS session ticket lifetime hint: 7200 (seconds)
TLS session ticket:
0000 - 95 40 b4 c5 12 44 16 3b-8e eb d7 57 12 d0 44 b5 [email protected].;...W..D.
0010 - 50 3b be 85 98 c0 90 cc-6d 26 32 c8 27 06 38 6f P;......m&2.'.8o
0020 - ec 00 a4 29 4d e2 73 38-f2 a4 ba e9 c6 84 1b 95 ...)M.s8........
0030 - 24 d1 48 de 02 bd 69 18-be 29 a5 56 65 0a e8 30 $.H...i..).Ve..0
0040 - 76 19 b7 6f 7b 3c 27 96-cd 03 ea 0f 9b 11 cf c3 v..o{<'.........
0050 - 99 75 e3 dc f9 8f 89 06-97 6d 49 62 b6 ea 5c e3 .u.......mIb..\.
0060 - 96 1c c3 a6 7e 1b cc c7-53 32 45 63 72 93 bb 89 ....~...S2Ecr...
0070 - 4a 8e 28 98 f7 1c 04 60-3d a4 89 38 30 4a 57 70 J.(....`=..80JWp
0080 - de 71 99 28 a8 04 cd 1a-dd 83 a8 f6 57 62 b3 1e .q.(........Wb..
0090 - 2d fa bf 02 fa 7b db 17-96 21 b7 43 e5 ed 84 ed -....{...!.C....
Start Time: 1598393617
Timeout : 7200 (sec)
Verify return code: 0 (ok)
Extended master secret: yes
---
*****
CONNECTED(00000003)
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 0 bytes and written 102 bytes
Verification: OK
---
New, (NONE), Cipher is (NONE)
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
Protocol : TLSv1
Cipher : 0000
Session-ID:
Session-ID-ctx:
Master-Key:
PSK identity: None
PSK identity hint: None
SRP username: None
Start Time: 1598393617
Timeout : 7200 (sec)
Verify return code: 0 (ok)
Extended master secret: no
---
!!!!!!
tshark capture
1035882 3202.183821121 10.42.0.80 → 10.43.0.10 DNS 103 Standard query 0x7e16 A www.example.com.default.svc.cluster.local
1035883 3202.183841699 10.42.0.80 → 10.43.0.10 DNS 103 Standard query 0x06ce AAAA www.example.com.default.svc.cluster.local
1035884 3202.183898283 10.43.0.10 → 10.42.0.80 DNS 196 Standard query response 0x06ce No such name AAAA www.example.com.default.svc.cluster.local SOA ns.dns.cluster.local
1035885 3202.183913852 10.43.0.10 → 10.42.0.80 DNS 196 Standard query response 0x7e16 No such name A www.example.com.default.svc.cluster.local SOA ns.dns.cluster.local
1035886 3202.183931564 10.42.0.80 → 10.43.0.10 DNS 95 Standard query 0xd0b7 A www.example.com.svc.cluster.local
1035887 3202.183938938 10.42.0.80 → 10.43.0.10 DNS 95 Standard query 0xc2a5 AAAA www.example.com.svc.cluster.local
1035888 3202.183981156 10.43.0.10 → 10.42.0.80 DNS 188 Standard query response 0xc2a5 No such name AAAA www.example.com.svc.cluster.local SOA ns.dns.cluster.local
1035889 3202.183999519 10.43.0.10 → 10.42.0.80 DNS 188 Standard query response 0xd0b7 No such name A www.example.com.svc.cluster.local SOA ns.dns.cluster.local
1035890 3202.184014567 10.42.0.80 → 10.43.0.10 DNS 91 Standard query 0x344a A www.example.com.cluster.local
1035891 3202.184022963 10.42.0.80 → 10.43.0.10 DNS 91 Standard query 0xd8f3 AAAA www.example.com.cluster.local
1035892 3202.184045674 10.43.0.10 → 10.42.0.80 DNS 184 Standard query response 0xd8f3 No such name AAAA www.example.com.cluster.local SOA ns.dns.cluster.local
1035893 3202.184065070 10.43.0.10 → 10.42.0.80 DNS 184 Standard query response 0x344a No such name A www.example.com.cluster.local SOA ns.dns.cluster.local
1035894 3202.184074457 10.42.0.80 → 10.43.0.10 DNS 77 Standard query 0xaa3d A www.example.com
1035895 3202.184080078 10.42.0.80 → 10.43.0.10 DNS 77 Standard query 0x288a AAAA www.example.com
1035896 3202.184105294 10.43.0.10 → 10.42.0.80 DNS 108 Standard query response 0xaa3d A www.example.com A 93.184.216.34
1035897 3202.184114872 10.43.0.10 → 10.42.0.80 DNS 120 Standard query response 0x288a AAAA www.example.com AAAA 2606:2800:220:1:248:1893:25c8:1946
1035898 3202.184187245 10.42.0.80 → 127.0.0.1 TCP 76 44796 → 4140 [SYN] Seq=0 Win=64860 Len=0 MSS=1410 SACK_PERM=1 TSval=765791812 TSecr=0 WS=128
1035899 3202.184194008 93.184.216.34 → 10.42.0.80 TCP 76 [TCP ACKed unseen segment] [TCP Retransmission] [TCP Port numbers reused] 443 → 44796 [SYN, ACK] Seq=2507374196 Ack=645700291 Win=65483 Len=0 MSS=65495 SACK_PERM=1 TSval=3305932945 TSecr=765791812 WS=128
1035900 3202.184198927 10.42.0.80 → 127.0.0.1 TCP 68 44796 → 4140 [ACK] Seq=1 Ack=1 Win=64896 Len=0 TSval=765791812 TSecr=3305932945
1035901 3202.184261432 10.42.0.80 → 127.0.0.1 TLSv1 170 Client Hello
1035902 3202.184265549 93.184.216.34 → 10.42.0.80 TCP 68 [TCP ACKed unseen segment] 443 → 44796 [ACK] Seq=2507374197 Ack=645700393 Win=65408 Len=0 TSval=3305932945 TSecr=765791812
1035903 3202.184420986 10.42.0.80 → 93.184.216.34 TCP 76 44798 → 443 [SYN] Seq=0 Win=64860 Len=0 MSS=1410 SACK_PERM=1 TSval=765791812 TSecr=0 WS=128
1035904 3202.188019561 93.184.216.34 → 10.42.0.80 TLSv1 760 Application Data, Application Data, Application Data, Application Data
1035905 3202.188025712 10.42.0.80 → 93.184.216.34 TCP 68 [TCP ACKed unseen segment] 44794 → 443 [ACK] Seq=365 Ack=5354 Win=497 Len=0 TSval=765791816 TSecr=3624231900
1035906 3202.188076776 93.184.216.34 → 10.42.0.80 TLSv1 760 [TCP ACKed unseen segment] [TCP Spurious Retransmission] , Application Data, Application Data, Application Data, Application Data
1035907 3202.188085162 10.42.0.80 → 127.0.0.1 TCP 56 44792 → 4140 [RST] Seq=365 Win=0 Len=0
1035908 3202.188120437 93.184.216.34 → 10.42.0.80 TLSv1 109 Encrypted Alert
1035909 3202.188123933 10.42.0.80 → 93.184.216.34 TCP 68 [TCP ACKed unseen segment] 44794 → 443 [ACK] Seq=365 Ack=5395 Win=502 Len=0 TSval=765791816 TSecr=3624231900
1035910 3202.188230850 93.184.216.34 → 10.42.0.80 TCP 68 443 → 44794 [FIN, ACK] Seq=1280797937 Ack=645267399 Win=67072 Len=0 TSval=3624231900 TSecr=765791809
1035911 3202.188235498 10.42.0.80 → 93.184.216.34 TCP 68 [TCP ACKed unseen segment] 44794 → 443 [ACK] Seq=365 Ack=5396 Win=502 Len=0 TSval=765791816 TSecr=3624231900
1035912 3202.191858058 93.184.216.34 → 10.42.0.80 TCP 76 443 → 44798 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=1460 SACK_PERM=1 TSval=2407782645 TSecr=765791812 WS=512
1035913 3202.191865271 10.42.0.80 → 93.184.216.34 TCP 68 44798 → 443 [ACK] Seq=1 Ack=1 Win=64896 Len=0 TSval=765791819 TSecr=2407782645
1035914 3202.191962941 10.42.0.80 → 93.184.216.34 TLSv1 170 Client Hello
1035915 3202.199557753 93.184.216.34 → 10.42.0.80 TCP 68 443 → 44798 [ACK] Seq=1 Ack=103 Win=65536 Len=0 TSval=2407782653 TSecr=765791819
1035916 3202.203158812 93.184.216.34 → 10.42.0.80 TLSv1 1466 Server Hello
1035917 3202.203163721 10.42.0.80 → 93.184.216.34 TCP 68 44798 → 443 [ACK] Seq=103 Ack=1399 Win=63616 Len=0 TSval=765791831 TSecr=2407782656
1035918 3202.203247115 93.184.216.34 → 10.42.0.80 TLSv1 1466 [TCP ACKed unseen segment] [TCP Spurious Retransmission] , Encrypted Handshake Message
1035919 3202.203253537 10.42.0.80 → 127.0.0.1 TCP 68 44796 → 4140 [ACK] Seq=103 Ack=1399 Win=64256 Len=0 TSval=765791831 TSecr=3305932964
1035920 3202.203295173 93.184.216.34 → 10.42.0.80 TCP 1466 443 → 44798 [ACK] Seq=1399 Ack=103 Win=65536 Len=1398 TSval=2407782656 TSecr=765791819 [TCP segment of a reassembled PDU]
1035921 3202.203297287 10.42.0.80 → 93.184.216.34 TCP 68 44798 → 443 [ACK] Seq=103 Ack=2797 Win=63104 Len=0 TSval=765791831 TSecr=2407782656
1035922 3202.203362267 93.184.216.34 → 10.42.0.80 TCP 1466 [TCP ACKed unseen segment] [TCP Spurious Retransmission] 443 → 44796 [PSH, ACK] Seq=2507375595 Ack=645700393 Win=65536 Len=1398 TSval=3305932964 TSecr=765791831 [TCP segment of a reassembled PDU]
1035923 3202.203366364 10.42.0.80 → 127.0.0.1 TCP 68 44796 → 4140 [ACK] Seq=103 Ack=2797 Win=64256 Len=0 TSval=765791831 TSecr=3305932964
1035924 3202.203432747 93.184.216.34 → 10.42.0.80 TLSv1 1368 Certificate [TCP segment of a reassembled PDU]
1035925 3202.203434941 10.42.0.80 → 93.184.216.34 TCP 68 44798 → 443 [ACK] Seq=103 Ack=4097 Win=63104 Len=0 TSval=765791831 TSecr=2407782656
1035926 3202.203504459 93.184.216.34 → 10.42.0.80 TLSv1 1368 [TCP ACKed unseen segment] [TCP Spurious Retransmission] , Encrypted Handshake Message [TCP segment of a reassembled PDU]
1035927 3202.203508045 10.42.0.80 → 127.0.0.1 TCP 68 44796 → 4140 [ACK] Seq=103 Ack=4097 Win=64256 Len=0 TSval=765791831 TSecr=3305932964
1035928 3202.203544913 93.184.216.34 → 10.42.0.80 TLSv1 395 Server Key Exchange, Server Hello Done
1035929 3202.203547147 10.42.0.80 → 93.184.216.34 TCP 68 44798 → 443 [ACK] Seq=103 Ack=4424 Win=63104 Len=0 TSval=765791831 TSecr=2407782656
1035930 3202.203598502 93.184.216.34 → 10.42.0.80 TLSv1 395 [TCP ACKed unseen segment] [TCP Spurious Retransmission] , Encrypted Handshake Message, Encrypted Handshake Message
1035931 3202.203602389 10.42.0.80 → 127.0.0.1 TCP 68 44796 → 4140 [ACK] Seq=103 Ack=4424 Win=64128 Len=0 TSval=765791831 TSecr=3305932964
1035932 3202.204547319 10.42.0.80 → 127.0.0.1 TLSv1 206 Client Key Exchange, Change Cipher Spec, Encrypted Handshake Message
1035933 3202.204552017 93.184.216.34 → 10.42.0.80 TCP 68 [TCP ACKed unseen segment] 443 → 44796 [ACK] Seq=2507378620 Ack=645700531 Win=65408 Len=0 TSval=3305932965 TSecr=765791832
1035934 3202.204595718 10.42.0.80 → 93.184.216.34 TLSv1 206 Client Key Exchange, Change Cipher Spec, Encrypted Handshake Message
1035935 3202.212396580 93.184.216.34 → 10.42.0.80 TLSv1 306 New Session Ticket, Change Cipher Spec, Encrypted Handshake Message
1035936 3202.212402030 10.42.0.80 → 93.184.216.34 TCP 68 44798 → 443 [ACK] Seq=241 Ack=4662 Win=64128 Len=0 TSval=765791840 TSecr=2407782666
1035937 3202.212463192 93.184.216.34 → 10.42.0.80 TLSv1 306 [TCP ACKed unseen segment] [TCP Spurious Retransmission] , Encrypted Handshake Message, Change Cipher Spec, Encrypted Handshake Message
1035938 3202.212467981 10.42.0.80 → 127.0.0.1 TCP 68 44796 → 4140 [ACK] Seq=241 Ack=4662 Win=64256 Len=0 TSval=765791840 TSecr=3305932973
1035939 3202.212707201 10.42.0.80 → 127.0.0.1 TLSv1 150 Application Data, Application Data
1035940 3202.212711890 93.184.216.34 → 10.42.0.80 TCP 68 [TCP ACKed unseen segment] 443 → 44796 [ACK] Seq=2507378858 Ack=645700613 Win=65536 Len=0 TSval=3305932973 TSecr=765791840
1035941 3202.212730384 10.42.0.80 → 127.0.0.1 TLSv1 109 Encrypted Alert
1035942 3202.212733370 93.184.216.34 → 10.42.0.80 TCP 68 [TCP ACKed unseen segment] 443 → 44796 [ACK] Seq=2507378858 Ack=645700654 Win=65536 Len=0 TSval=3305932973 TSecr=765791840
1035943 3202.212742206 10.42.0.80 → 127.0.0.1 TCP 68 44796 → 4140 [FIN, ACK] Seq=364 Ack=4662 Win=64256 Len=0 TSval=765791840 TSecr=3305932973
1035944 3202.212770017 10.42.0.80 → 93.184.216.34 TLSv1 191 Application Data, Application Data, Encrypted Alert
1035945 3202.212825900 10.42.0.80 → 93.184.216.34 TCP 68 44798 → 443 [FIN, ACK] Seq=364 Ack=4662 Win=64256 Len=0 TSval=765791840 TSecr=2407782666
1035946 3202.215321164 10.42.0.80 → 10.43.0.10 DNS 103 Standard query 0xacf2 A www.example.com.default.svc.cluster.local
1035947 3202.215345619 10.42.0.80 → 10.43.0.10 DNS 103 Standard query 0x9a88 AAAA www.example.com.default.svc.cluster.local
1035948 3202.215435534 10.43.0.10 → 10.42.0.80 DNS 196 Standard query response 0x9a88 No such name AAAA www.example.com.default.svc.cluster.local SOA ns.dns.cluster.local
1035949 3202.215457004 10.43.0.10 → 10.42.0.80 DNS 196 Standard query response 0xacf2 No such name A www.example.com.default.svc.cluster.local SOA ns.dns.cluster.local
1035950 3202.215473745 10.42.0.80 → 10.43.0.10 DNS 95 Standard query 0xa804 A www.example.com.svc.cluster.local
1035951 3202.215481529 10.42.0.80 → 10.43.0.10 DNS 95 Standard query 0xb884 AAAA www.example.com.svc.cluster.local
1035952 3202.215528996 10.43.0.10 → 10.42.0.80 DNS 188 Standard query response 0xa804 No such name A www.example.com.svc.cluster.local SOA ns.dns.cluster.local
1035953 3202.215544685 10.43.0.10 → 10.42.0.80 DNS 188 Standard query response 0xb884 No such name AAAA www.example.com.svc.cluster.local SOA ns.dns.cluster.local
1035954 3202.215556778 10.42.0.80 → 10.43.0.10 DNS 91 Standard query 0x62dc A www.example.com.cluster.local
1035955 3202.215563530 10.42.0.80 → 10.43.0.10 DNS 91 Standard query 0x2a37 AAAA www.example.com.cluster.local
1035956 3202.215590199 10.43.0.10 → 10.42.0.80 DNS 184 Standard query response 0x2a37 No such name AAAA www.example.com.cluster.local SOA ns.dns.cluster.local
1035957 3202.215600468 10.43.0.10 → 10.42.0.80 DNS 184 Standard query response 0x62dc No such name A www.example.com.cluster.local SOA ns.dns.cluster.local
1035958 3202.215611078 10.42.0.80 → 10.43.0.10 DNS 77 Standard query 0xe6bd A www.example.com
1035959 3202.215616918 10.42.0.80 → 10.43.0.10 DNS 77 Standard query 0x2847 AAAA www.example.com
1035960 3202.215652975 10.43.0.10 → 10.42.0.80 DNS 120 Standard query response 0x2847 AAAA www.example.com AAAA 2606:2800:220:1:248:1893:25c8:1946
1035961 3202.215670797 10.43.0.10 → 10.42.0.80 DNS 108 Standard query response 0xe6bd A www.example.com A 93.184.216.34
1035962 3202.215740496 10.42.0.80 → 127.0.0.1 TCP 76 44800 → 4140 [SYN] Seq=0 Win=64860 Len=0 MSS=1410 SACK_PERM=1 TSval=765791843 TSecr=0 WS=128
1035963 3202.215747479 93.184.216.34 → 10.42.0.80 TCP 76 443 → 44800 [SYN, ACK] Seq=0 Ack=1 Win=65483 Len=0 MSS=65495 SACK_PERM=1 TSval=3305932976 TSecr=765791843 WS=128
1035964 3202.215752889 10.42.0.80 → 127.0.0.1 TCP 68 44800 → 4140 [ACK] Seq=1 Ack=1 Win=64896 Len=0 TSval=765791843 TSecr=3305932976
1035965 3202.215815915 10.42.0.80 → 127.0.0.1 TLSv1 170 Client Hello
1035966 3202.215820273 93.184.216.34 → 10.42.0.80 TCP 68 443 → 44800 [ACK] Seq=1 Ack=103 Win=65408 Len=0 TSval=3305932976 TSecr=765791843
1035967 3202.215951374 10.42.0.80 → 93.184.216.34 TCP 76 44802 → 443 [SYN] Seq=0 Win=64860 Len=0 MSS=1410 SACK_PERM=1 TSval=765791843 TSecr=0 WS=128
1035968 3202.219721084 93.184.216.34 → 10.42.0.80 TLSv1 760 Application Data, Application Data, Application Data, Application Data
1035969 3202.219727015 10.42.0.80 → 93.184.216.34 TCP 68 44798 → 443 [ACK] Seq=365 Ack=5354 Win=63616 Len=0 TSval=765791847 TSecr=2407782673
1035970 3202.219772749 93.184.216.34 → 10.42.0.80 TLSv1 760 [TCP ACKed unseen segment] [TCP Spurious Retransmission] , Application Data, Application Data, Application Data, Application Data
1035971 3202.219780944 10.42.0.80 → 127.0.0.1 TCP 56 44796 → 4140 [RST] Seq=365 Win=0 Len=0
1035972 3202.219821810 93.184.216.34 → 10.42.0.80 TLSv1 109 Encrypted Alert
1035973 3202.219825737 10.42.0.80 → 93.184.216.34 TCP 68 44798 → 443 [ACK] Seq=365 Ack=5395 Win=64256 Len=0 TSval=765791847 TSecr=2407782673
1035974 3202.219933094 93.184.216.34 → 10.42.0.80 TCP 68 443 → 44798 [FIN, ACK] Seq=5395 Ack=364 Win=67072 Len=0 TSval=2407782673 TSecr=765791840
1035975 3202.219936591 10.42.0.80 → 93.184.216.34 TCP 68 44798 → 443 [ACK] Seq=365 Ack=5396 Win=64256 Len=0 TSval=765791847 TSecr=2407782673
1035976 3202.219934317 93.184.216.34 → 10.42.0.80 TCP 68 443 → 44798 [ACK] Seq=5396 Ack=365 Win=67072 Len=0 TSval=2407782673 TSecr=765791840
1035977 3202.222844314 93.184.216.34 → 10.42.0.80 TCP 76 443 → 44802 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=1460 SACK_PERM=1 TSval=2087024196 TSecr=765791843 WS=512
1035978 3202.222850004 10.42.0.80 → 93.184.216.34 TCP 68 44802 → 443 [ACK] Seq=1 Ack=1 Win=64896 Len=0 TSval=765791850 TSecr=2087024196
1035979 3202.222943517 10.42.0.80 → 93.184.216.34 TLSv1 170 Client Hello
1035980 3202.230483147 93.184.216.34 → 10.42.0.80 TCP 68 443 → 44802 [ACK] Seq=1 Ack=103 Win=65536 Len=0 TSval=2087024204 TSecr=765791850
1035981 3202.233792430 93.184.216.34 → 10.42.0.80 TLSv1 1466 Server Hello
1035982 3202.233797790 10.42.0.80 → 93.184.216.34 TCP 68 44802 → 443 [ACK] Seq=103 Ack=1399 Win=63616 Len=0 TSval=765791861 TSecr=2087024206
1035983 3202.233879029 93.184.216.34 → 10.42.0.80 TLSv1 1466 Server Hello
1035984 3202.233885451 10.42.0.80 → 127.0.0.1 TCP 68 44800 → 4140 [ACK] Seq=103 Ack=1399 Win=64256 Len=0 TSval=765791861 TSecr=3305932994
1035985 3202.233928651 93.184.216.34 → 10.42.0.80 TCP 1466 443 → 44802 [ACK] Seq=1399 Ack=103 Win=65536 Len=1398 TSval=2087024206 TSecr=765791850 [TCP segment of a reassembled PDU]
1035986 3202.233930995 10.42.0.80 → 93.184.216.34 TCP 68 44802 → 443 [ACK] Seq=103 Ack=2797 Win=63104 Len=0 TSval=765791861 TSecr=2087024206
1035987 3202.234019368 93.184.216.34 → 10.42.0.80 TCP 1466 443 → 44800 [PSH, ACK] Seq=1399 Ack=103 Win=65536 Len=1398 TSval=3305932995 TSecr=765791861 [TCP segment of a reassembled PDU]
1035988 3202.234024447 10.42.0.80 → 127.0.0.1 TCP 68 44800 → 4140 [ACK] Seq=103 Ack=2797 Win=64256 Len=0 TSval=765791862 TSecr=3305932995
1035989 3202.234060804 93.184.216.34 → 10.42.0.80 TLSv1 1368 Certificate [TCP segment of a reassembled PDU]
1035990 3202.234062998 10.42.0.80 → 93.184.216.34 TCP 68 44802 → 443 [ACK] Seq=103 Ack=4097 Win=63104 Len=0 TSval=765791862 TSecr=2087024206
1035991 3202.234139028 93.184.216.34 → 10.42.0.80 TLSv1 1368 Certificate [TCP segment of a reassembled PDU]
1035992 3202.234142975 10.42.0.80 → 127.0.0.1 TCP 68 44800 → 4140 [ACK] Seq=103 Ack=4097 Win=64256 Len=0 TSval=765791862 TSecr=3305932995
1035993 3202.234168663 93.184.216.34 → 10.42.0.80 TLSv1 395 Server Key Exchange, Server Hello Done
1035994 3202.234170376 10.42.0.80 → 93.184.216.34 TCP 68 44802 → 443 [ACK] Seq=103 Ack=4424 Win=63104 Len=0 TSval=765791862 TSecr=2087024206
1035995 3202.234251525 93.184.216.34 → 10.42.0.80 TLSv1 395 Server Key Exchange, Server Hello Done
1035996 3202.234255643 10.42.0.80 → 127.0.0.1 TCP 68 44800 → 4140 [ACK] Seq=103 Ack=4424 Win=64128 Len=0 TSval=765791862 TSecr=3305932995
1035997 3202.235118391 10.42.0.80 → 127.0.0.1 TLSv1 206 Client Key Exchange, Change Cipher Spec, Encrypted Handshake Message
1035998 3202.235124482 93.184.216.34 → 10.42.0.80 TCP 68 443 → 44800 [ACK] Seq=4424 Ack=241 Win=65408 Len=0 TSval=3305932996 TSecr=765791863
1035999 3202.235185074 10.42.0.80 → 93.184.216.34 TLSv1 206 Client Key Exchange, Change Cipher Spec, Encrypted Handshake Message
1036000 3202.243302869 93.184.216.34 → 10.42.0.80 TLSv1 306 New Session Ticket, Change Cipher Spec, Encrypted Handshake Message
1036001 3202.243309381 10.42.0.80 → 93.184.216.34 TCP 68 44802 → 443 [ACK] Seq=241 Ack=4662 Win=64128 Len=0 TSval=765791871 TSecr=2087024217
1036002 3202.243383067 93.184.216.34 → 10.42.0.80 TLSv1 306 New Session Ticket, Change Cipher Spec, Encrypted Handshake Message
1036003 3202.243388046 10.42.0.80 → 127.0.0.1 TCP 68 44800 → 4140 [ACK] Seq=241 Ack=4662 Win=64256 Len=0 TSval=765791871 TSecr=3305933004
1036004 3202.243565422 10.42.0.80 → 127.0.0.1 TLSv1 150 Application Data, Application Data
1036005 3202.243569370 93.184.216.34 → 10.42.0.80 TCP 68 443 → 44800 [ACK] Seq=4662 Ack=323 Win=65536 Len=0 TSval=3305933004 TSecr=765791871
1036006 3202.243583576 10.42.0.80 → 127.0.0.1 TLSv1 109 Encrypted Alert
1036007 3202.243585740 93.184.216.34 → 10.42.0.80 TCP 68 443 → 44800 [ACK] Seq=4662 Ack=364 Win=65536 Len=0 TSval=3305933004 TSecr=765791871
1036008 3202.243592302 10.42.0.80 → 127.0.0.1 TCP 68 44800 → 4140 [FIN, ACK] Seq=364 Ack=4662 Win=64256 Len=0 TSval=765791871 TSecr=3305933004
1036009 3202.243659646 10.42.0.80 → 93.184.216.34 TLSv1 191 Application Data, Application Data, Encrypted Alert
1036010 3202.243718013 10.42.0.80 → 93.184.216.34 TCP 68 44802 → 443 [FIN, ACK] Seq=364 Ack=4662 Win=64256 Len=0 TSval=765791871 TSecr=2087024217
1036011 3202.245897195 10.42.0.80 → 10.43.0.10 DNS 103 Standard query 0x20eb A www.example.com.default.svc.cluster.local
1036012 3202.245917723 10.42.0.80 → 10.43.0.10 DNS 103 Standard query 0xe878 AAAA www.example.com.default.svc.cluster.local
1036013 3202.245966192 10.43.0.10 → 10.42.0.80 DNS 196 Standard query response 0xe878 No such name AAAA www.example.com.default.svc.cluster.local SOA ns.dns.cluster.local
1036014 3202.245985658 10.43.0.10 → 10.42.0.80 DNS 196 Standard query response 0x20eb No such name A www.example.com.default.svc.cluster.local SOA ns.dns.cluster.local
1036015 3202.246002399 10.42.0.80 → 10.43.0.10 DNS 95 Standard query 0xd6da A www.example.com.svc.cluster.local
1036016 3202.246009832 10.42.0.80 → 10.43.0.10 DNS 95 Standard query 0xec40 AAAA www.example.com.svc.cluster.local
1036017 3202.246047973 10.43.0.10 → 10.42.0.80 DNS 188 Standard query response 0xec40 No such name AAAA www.example.com.svc.cluster.local SOA ns.dns.cluster.local
1036018 3202.246061457 10.43.0.10 → 10.42.0.80 DNS 188 Standard query response 0xd6da No such name A www.example.com.svc.cluster.local SOA ns.dns.cluster.local
1036019 3202.246072979 10.42.0.80 → 10.43.0.10 DNS 91 Standard query 0xdaca A www.example.com.cluster.local
1036020 3202.246079130 10.42.0.80 → 10.43.0.10 DNS 91 Standard query 0x3258 AAAA www.example.com.cluster.local
1036021 3202.246102964 10.43.0.10 → 10.42.0.80 DNS 184 Standard query response 0x3258 No such name AAAA www.example.com.cluster.local SOA ns.dns.cluster.local
1036022 3202.246122830 10.43.0.10 → 10.42.0.80 DNS 184 Standard query response 0xdaca No such name A www.example.com.cluster.local SOA ns.dns.cluster.local
1036023 3202.246133540 10.42.0.80 → 10.43.0.10 DNS 77 Standard query 0xd662 A www.example.com
1036024 3202.246139471 10.42.0.80 → 10.43.0.10 DNS 77 Standard query 0xb46f AAAA www.example.com
1036025 3202.246171380 10.43.0.10 → 10.42.0.80 DNS 120 Standard query response 0xb46f AAAA www.example.com AAAA 2606:2800:220:1:248:1893:25c8:1946
1036026 3202.246185356 10.43.0.10 → 10.42.0.80 DNS 108 Standard query response 0xd662 A www.example.com A 93.184.216.34
1036027 3202.246249684 10.42.0.80 → 127.0.0.1 TCP 76 [TCP Port numbers reused] 44804 → 4140 [SYN] Seq=0 Win=64860 Len=0 MSS=1410 SACK_PERM=1 TSval=765791874 TSecr=0 WS=128
1036028 3202.246256657 93.184.216.34 → 10.42.0.80 TCP 76 [TCP Previous segment not captured] [TCP Port numbers reused] 443 → 44804 [SYN, ACK] Seq=645801769 Ack=645801819 Win=65483 Len=0 MSS=65495 SACK_PERM=1 TSval=3305933007 TSecr=765791874 WS=128
1036029 3202.246261325 10.42.0.80 → 127.0.0.1 TCP 68 44804 → 4140 [ACK] Seq=1 Ack=1 Win=64896 Len=0 TSval=765791874 TSecr=3305933007
1036030 3202.246313411 10.42.0.80 → 127.0.0.1 TLSv1 170 Client Hello
1036031 3202.246317228 93.184.216.34 → 10.42.0.80 TCP 68 443 → 44804 [ACK] Seq=645801770 Ack=645801921 Win=65408 Len=0 TSval=3305933007 TSecr=765791874
1036032 3202.246466694 10.42.0.80 → 93.184.216.34 TCP 76 [TCP Port numbers reused] 44806 → 443 [SYN] Seq=0 Win=64860 Len=0 MSS=1410 SACK_PERM=1 TSval=765791874 TSecr=0 WS=128
👀1
Ah, I see: the difference is that the openssl s_client command doesn't actually wait for an HTTP request/response pair to complete, so here we still see the proxy receiving data on conns from previous requests in some places. Looks like the last request _does_ still fail with a timeout.
In particular, OpenSSL claims that it "wrote 102 bytes and read 0":
` *****
CONNECTED(00000003)
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 0 bytes and written 102 bytes
Verification: OK
so i believe that's the request on port 44804 here:
[ 3205.754274463s] TRACE ThreadId(23) outbound: linkerd2_proxy_transport::listen: Accepted peer.addr=10.42.0.80:44804 orig.addr=Some(V4(93.184.216.34:443))
[ 3205.754282057s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: new
[ 3205.754284432s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: enter
[ 3205.754287798s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: exit
[ 3205.754300231s] INFO ThreadId(23) outbound: linkerd2_app: exit
[ 3205.754303246s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: enter
[ 3205.754308997s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_stack_tracing: poll_ready
[ 3205.754311952s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_stack_tracing: ready=true
[ 3205.754313976s] DEBUG ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_outbound::prevent_loop: addr=93.184.216.34:443 self.port=4140
[ 3205.754316340s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_stack_tracing: make_service target=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }
[ 3205.754321049s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: new
[ 3205.754323263s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.754326128s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.754328262s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.754329785s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: making
[ 3205.754331648s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: ready=true
[ 3205.754334934s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.754337830s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_stack_tracing: new_service target=Addrs { local: V4(10.42.0.80:44804), peer: V4(10.42.0.80:44804), orig_dst: Some(V4(93.184.216.34:443)) }
[ 3205.754342238s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:source{target.addr=93.184.216.34:443}: linkerd2_app_outbound: new
[ 3205.754343921s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:source{target.addr=93.184.216.34:443}: linkerd2_app_outbound: enter
[ 3205.754346496s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:source{target.addr=93.184.216.34:443}: linkerd2_app_outbound: exit
[ 3205.754360612s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_io::peek: poll_peek=Ready(Ok(102))
[ 3205.754363357s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_io::peek: peeked.len=102
[ 3205.754367084s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_proxy_http::detect: Forwarding TCP
[ 3205.754369198s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.754371382s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: poll ready
[ 3205.754372944s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_stack_tracing: ready=true
[ 3205.754374708s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.754376471s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.754403431s] DEBUG ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_proxy_transport::tls::client: peer.identity=None(NotHttp)
[ 3205.754406035s] DEBUG ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_proxy_transport::connect: Connecting peer.addr=93.184.216.34:443
[ 3205.754410754s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.754413449s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3205.754415202s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_proxy_tcp::forward: in accept future!
[ 3205.754418348s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: new
[ 3205.754421063s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: enter
[ 3205.754471045s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: exit
[ 3205.754474732s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.754476906s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: exit
[ 3205.759538134s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44800}: linkerd2_app_core::serve: enter
[ ... request on port 44800 snipped out ... ]
[ 3205.759835070s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3205.759837555s] TRACE ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: close time.busy=1.16ms time.idle=34.9ms
[ 3205.759841903s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}:source{target.addr=93.184.216.34:443}: linkerd2_app_outbound: close time.busy=3.22µs time.idle=36.0ms
[ 3205.759849036s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}: linkerd2_app_core::serve: Connection closed error=Transport endpoint is not connected (os error 107)
[ 3205.759853885s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}: linkerd2_app_core::serve: exit
[ 3205.759856390s] INFO ThreadId(23) outbound:accept{peer.addr=10.42.0.80:44800}: linkerd2_app_core::serve: close time.busy=1.34ms time.idle=34.7ms
[ 3206.755859753s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: enter
[ 3206.755877626s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: enter
[ 3206.755882084s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: enter
[ 3206.755906068s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: exit
[ 3206.755910005s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}:connect: linkerd2_proxy_tcp::forward: close time.busy=73.8µs time.idle=1.00s
[ 3206.755936354s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: exit
[ 3206.755939980s] TRACE ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}:tcp_forward{endpoint=TcpEndpoint { addr: V4(93.184.216.34:443), identity: None(NotHttp) }}: linkerd2_app_outbound: close time.busy=169µs time.idle=1.00s
[ 3206.755944719s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}:source{target.addr=93.184.216.34:443}: linkerd2_app_outbound: close time.busy=2.58µs time.idle=1.00s
[ 3206.755974203s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: Connection closed error=request timed out
[ 3206.755978872s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: exit
[ 3206.755981076s] INFO ThreadId(22) outbound:accept{peer.addr=10.42.0.80:44804}: linkerd2_app_core::serve: close time.busy=297µs time.idle=1.00s
where it does, indeed, look like we peeked at the first 102 bytes of the client connection.
hawkw
on 26 Aug 2020
A quick update: this appears to be a bug in an underlying library (tokio and/or mio) --- I can reproduce it with code that uses tokio without Linkerd. Will investigate further and fix it upstream.
hawkw
on 27 Aug 2020
🎉2
So, I have been having some kind of similar problem. We have been talking about it in slack: https://linkerd.slack.com/archives/C89RTCWJF/p1600722815079100
Here my findings:
In my case most of the errors disappear when I set the LINKERD2_PROXY_OUTBOUND_CONNECT_TIMEOUT to 2s as @hawkw mentioned. But still, even with that I got some so I tried to find out why.
To analize a little bit what is going on I launched 2 pods without linkerd, one in a cluster with the problem and one in a cluster without the problem, and I ran this:
H=[https host name]
BAD_THRESHOLD=900
n_good=0
n_bad=0
t=0
t_bad=0
for i in $(seq 0 5000); do
{
n_good=$(($n_good+1))
SDATE=$(date +%s%N | cut -b1-13)
echo "GET /" | openssl s_client -connect $H:443 -no_tls1_1 &> /dev/null
ret=$?
EDATE=$(date +%s%N | cut -b1-13)
T=$(($EDATE-$SDATE))
t=$(($t+$T))
if [ $T -gt $BAD_THRESHOLD ]; then
echo $T
n_bad=$(($n_bad+1))
t_bad=$(($t_bad+$T))
fi
if [ $ret -ne 0 ]; then
echo -n
#pass
#echo "FAILED"
#break
fi
}; done
taverage=$(($t/$n_good))
echo "Avg ms: $taverage"
echo "Avg ms only good: $((($t-$t_bad)/($n_good-$n_bad)))"
echo "FAILED: $n_bad/$n_good"
This led me to see the calls that took more than 900ms and also see if the average of both clusters was similar. In my case, the average was very similar bu, in the bad cluster I saw a lot of requests taking more than 1s or 3s such as:
3048
1052
1022
1043
1021
3069
1052
1048
3064
1617
1054
1052
1043
This pattern 10XX and 30XX instead of 1[1-9]XX led me to think it could be a timeout, and 1s and 3s actually sounded like tcp retries. So, I opened a second terminal and while running the script I also ran:
tshark -Y tcp.analysis.retransmission
And well, kind of as expected, I see a retransmission happening everytime I get an over-the threshold request.
Also, I ran this in 4 clusters. 2 KOPS and 2 EKS. It could be luck, because maybe 4 is not enough to conclude this, but it seems this is happening to me in EKS but not in KOPS. I thought it could be the AWS CNI, but it turns out this happens also if I run it from the node instead of a pod, skipping the CNI. And this is where I am at now, trying to figure it out why all these retransmissions on EKS clusters. Just to give some numbers, out of 20000 requests, in KOPS I got 1 failure, while in EKS I got 186.
dcodix
on 23 Sep 2020
The most recent edge release, edge-20.10.3 makes substantial changes to the TCP forwarding stack. I'm not 100% confident that this resolves your issue, but it would be helpful to confirm that this issue persists with these changes.
olix0r
on 16 Oct 2020
Was this page helpful?
0 / 5 - 0 ratings
Related issues
adleong
·
4Comments
geekmush
·
4Comments
skalinets
·
3Comments
briansmith
·
4Comments
wmorgan
·
3Comments
Most helpful comment
A quick update: this appears to be a bug in an underlying library (
tokioand/ormio) --- I can reproduce it with code that usestokiowithout Linkerd. Will investigate further and fix it upstream.