In TLSProxy::Proxy::clientstart(), don't cut off all com at once by levitte · Pull Request #5067 · openssl/openssl

levitte · 2018-01-12T20:19:16Z

Whenever the client or the server would cut off communication, the
proxy would immediately take down the proxy entirely. However, it's
very possible that just because one side stopped communicating, the
other side might still have a packet on its way.

Since the proxy runs filters, and most of all checks for specific
records to see if the communication was successful or not, it seems
important that none of them are ignored.

Therefore, recode the loop to simply ignore the channel where
communication has stopped, but continue to receive data on the other
until that one shuts down as well.

levitte · 2018-01-12T20:20:02Z

Hopefully, this will fix the strange test failures we've seen on Travis lately, and possibly similar issues I've observed on Cygwin as well

bernd-edlinger · 2018-01-12T20:38:51Z

I am not sure if a
$SIG{PIPE} = "IGNORE";
may additionally be necessary.
in the trace I had sent an hour ago, I saw
no error from the sysread but instead a SIGPIPE in the syswrite.

bernd-edlinger · 2018-01-12T20:48:28Z

util/perl/TLSProxy/Proxy.pm

I think here we need to disable SIGPIPE with:
SIG{PIPE} = "IGNORE";

levitte · 2018-01-12T20:52:27Z

in the trace I had sent an hour ago, I saw no error from the sysread but instead a SIGPIPE in the syswrite.

Yeah, but note how in the change here, I avoid writing to a socket that has been removed from $sel. That's what the $sel->exists($socket) check does.

levitte · 2018-01-12T20:53:05Z

So if you wouldn't mind running your loop with this PR, that would be great!

levitte · 2018-01-12T20:54:08Z

And sure, it really needed, I will add an ignore of SIGPIPE

bernd-edlinger · 2018-01-12T20:54:34Z

util/perl/TLSProxy/Proxy.pm

I wonder why the "Connection closed" is no longer in the V=1 trace.

No "Server connection closed" or "Client connection closed" either?

so, why is the new print to STDERR, and guarded by self->debug ?

You know, good point. I'll add that back...

Yes, not a single "Server|Client connection closed",
only one "Error on client end: Connection reset by peer"

bernd-edlinger · 2018-01-12T21:20:17Z

I am now running this PR with added SIG{PIPE} = "IGNORE"
with strace, would you like me to continue that test-loop or start
it again without that change?

levitte · 2018-01-12T21:22:59Z

For maximum data coverage, I'd encourage you to continue that test loop, and then do another without SIG{PIPE} = "IGNORE" ;-)

No pressure, though

kaduk · 2018-01-12T21:25:59Z

My first build+test at commit c288c60fe8347e662688f9644e56ce29941e9b86 managed to get a

../test/recipes/70-test_sslsessiontick.t ........... Dubious, test returned 104 (wstat 26624, 0x6800)
Failed 7/10 subtests

But that used my normal build invocation that lacked V=1, so I'll fire up my testing loop as well.

bernd-edlinger · 2018-01-12T21:28:49Z

Yep, got the same, after 49 iterations,
but with strace this time no SIGPIPE, but something different...
are you interested in the strace and log files ?

kaduk · 2018-01-12T21:30:09Z

I wonder what he cost/benefit analysis would be for having output from the different processes be sent to separate logfiles or prefixed with a pid+timestamp or something.

levitte · 2018-01-12T21:37:29Z

Good questions. Feel free to experiment, it's a good thing if a few more get acquainted with the TLSProxy code. Me, I need to call it a night...

bernd-edlinger · 2018-01-12T22:01:31Z

With this patch failure mode is a bit different, "No progress made" then test breaks immediately.

levitte · 2018-01-12T22:04:18Z

I'm interested in that log file

bernd-edlinger · 2018-01-12T22:11:11Z

So as requested, log file, and strace output from a41a612 with your patch.
test10.log

test10-strace.log

do you understand how to read the strace file, or need help ?

kaduk · 2018-01-12T22:36:21Z

fail-sslrecords.txt
Still running c288c60fe8347e662688f9644e56ce29941e9b86 in a loop with V=1 (but no strace), I got a synchronization failure (exerpt attached)

bernd-edlinger · 2018-01-13T14:44:22Z

In the attached strace file I see somthing that I don't understand.

grep ^26374 test10-strace.log prints the proxy process
grep ^26498 test10-strace.log prints the server process
grep ^26504 test10-strace.log prints the client process

what I think I see there, is the client does:
send "test" to proxy, read EOF from STDIN, send ALERT to proxy, close file.

26504 write(3, "\27\3\3\0\26test\n\27\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 27 <unfinished ...>
26504 <... write resumed> )             = 27
26504 select(4, [0 3], [], NULL, NULL <unfinished ...>
26504 <... select resumed> )            = 1 (in [0])
26504 read(0,  <unfinished ...>
26504 <... read resumed> "", 8192)      = 0
26504 write(2, "DONE\n", 5 <unfinished ...>
26504 <... write resumed> )             = 5
26504 write(3, "\27\3\3\0\23\1\0\25\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 24 <unfinished ...>
26504 <... write resumed> )             = 24
26504 close(3 <unfinished ...>
26504 <... close resumed> )             = 0
26504 exit_group(0)                     = ?
26504 +++ exited with 0 +++

but the proxy receives only the test and then ECONNRESET.

26374 select(8, [4 5], NULL, NULL, {1, 0} <unfinished ...>
26374 <... select resumed> )            = 1 (in [4], left {0, 999998})
26374 read(4,  <unfinished ...>
26374 <... read resumed> "\27\3\3\0\26test\n\27\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"
, 16384) = 27
26374 write(1, "Received client packet\n", 23 <unfinished ...>
...
26374 select(8, [4 5], NULL, NULL, {1, 0} <unfinished ...>
26374 <... select resumed> )            = 1 (in [4], left {0, 999452})
26374 read(4,  <unfinished ...>
26374 <... read resumed> 0x1e21be0, 16384) = -1 ECONNRESET (Connection reset by 
peer)

The SIGPIPE patch does not fix this,
but it happens just much more often with your patch.
Unclear why.

levitte · 2018-01-13T14:56:51Z

That's exactly the behavior I have observed on my cygwin installation. Why my patch makes it worse, I cannot say...

Gut feeling, I'm guessing that the client is taken down before all packets are actually sent out, and that cancels all packet queues. I don't know why this happens yet, and don't have time today, but I would start looking at do_ssl_shutdown (apps/s_client.c) and ssl3_shutdown (ssl/s3_lib.c).

levitte · 2018-01-13T14:57:33Z

This should probably be raised as a separate issue, BTW...

bernd-edlinger · 2018-01-15T11:34:07Z

I think I have now seen tests failures (without this patch) where
N=0; while make test TESTS=test_sslrecords V=1 >test$N.log; do N=$((N+1)); done; echo count=$N
fails. Unable to reproduce with strace, so I cannot be sure, but I believe the server shuts down
before the client.
Will continue the test loop with your patch installed.

bernd-edlinger

OK, thanks!

bernd-edlinger · 2018-01-15T14:01:05Z

I tried this to force the client to send the ALERT after the server exits, but did not work:

diff --git a/apps/s_client.c b/apps/s_client.c
index 218accf..ec5e893 100644
--- a/apps/s_client.c
+++ b/apps/s_client.c
@@ -3022,6 +3022,7 @@ int s_client_main(int argc, char **argv)

     ret = 0;
  shut:
+    usleep(1000000);
     if (in_init)
         print_stuff(bio_c_out, con, full_log);
     do_ssl_shutdown(con);

make test pass without this patch...

levitte · 2018-01-15T17:56:58Z

Ok, sounds like this isn't necessary then. Closing...

levitte · 2018-01-15T18:12:51Z

Oh, err, wait, I seem to be getting mixed messages... @bernd-edlinger, are you telling me I should merge this (i.e. listen to your approval) or that just closing was the right thing?

bernd-edlinger · 2018-01-15T18:27:28Z

Yes, no...

I had run the test_sslrecords loop on another machine (faster and more recent linux kernel),
and was experiencing a failure, twice in a row after 400-800 iterations. It was without this patch,
then I installed this patch. And it ran for quite a while, so I concluded that your
patch fixes that. However, while I actually did some other work, this it failed again.
with the "Error on client end" message. After more than 4800 iterations.

But my other experiment shows that the server does not race with the client
to close the socket, under normal conditions, right?

Currently my I have no Idea, what went wrong. When I start tracing too much
the problem stops to reproduce.

bernd-edlinger · 2018-01-15T20:00:41Z

for completeness this is how the test failed after 4939 iterations:

    Extended master secret: no
---
Connection closed
CONNECTION FAILURE
Waiting for server process to close: 16066
140534703527680:error:1408F081:SSL routines:ssl3_get_record:block cipher pad is wrong:ssl/record/ssl3_record.c:549:
   0 items in the session cache
   0 client connects (SSL_connect())
   0 client renegotiates (SSL_connect())
   0 client connects that finished
   1 server accepts (SSL_accept())
   0 server renegotiates (SSL_accept())
   0 server accepts that finished
   0 session cache hits
   0 session cache misses
   0 session cache timeouts
   0 callback cache hits
   0 cache full overflows (128 allowed)
Waiting for client process to close: 16067
ok 17 - Record not on boundary in TLS1.3 (Finished)
Proxy started on port 4453
Server command: ../../util/shlib_wrap.sh ../../apps/openssl s_server -no_comp -rev -engine ossltest -accept 4443 -cert ../../apps/server.pem -cert2 ../../apps/server.pem -naccept 1 -cipher AES128-SHA:TLS13-AES-128-GCM-SHA256
Client command: echo test | ../../util/shlib_wrap.sh ../../apps/openssl s_client -engine ossltest -connect localhost:4453
engine "ossltest" set.
engine "ossltest" set.
Connection opened
Using default temp DH parameters
ACCEPT
Received client packet
Packet length = 301
Processing flight 0
 Record 1 (client -> server)
  Content type: HANDSHAKE
  Version: TLS1.0
  Length: 296
  Message type: ClientHello
  Message Length: 292
    Client Version:771
    Session ID Len:32
    Ciphersuite len:62
    Compression Method Len:1
    Extensions Len:157

Forwarded packet length = 301

Received server packet
Packet length = 1543
Processing flight 1
 Record 1 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 122
  Message type: ServerHello
  Message Length: 118
    Server Version:771
    Session ID Len:32
    Ciphersuite:4865
    Compression Method:0
    Extensions Len:46
 Record 2 (server -> client)
  Content type: CCS
  Version: TLS1.2
  Length: 1
 Record 3 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 23
  Inner content type: HANDSHAKE
  Message type: EncryptedExtensions
  Message Length: 2
    Extensions Len:0
 Record 4 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 1033
  Inner content type: HANDSHAKE
  Message type: Certificate
  Message Length: 1012
    Context:
    Certificate List Len:1008
    Certificate Len:1003
    Extensions Len:0
 Record 5 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 281
  Inner content type: HANDSHAKE
  Message type: CertificateVerify
  Message Length: 260
    SigAlg:2052
    Signature Len:256
 Record 6 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 53
  Inner content type: HANDSHAKE
  Message type: Finished
  Message Length: 32

Forwarded packet length = 1579

depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
verify error:num=20:unable to get local issuer certificate
verify return:1
depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
verify error:num=21:unable to verify the first certificate
verify return:1
Received client packet
Packet length = 64
Processing flight 2
 Record 1 (client -> server)
  Content type: CCS
  Version: TLS1.2
  Length: 1
CONNECTED(00000003)
---
Certificate chain
 0 s:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
   i:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA
---
Server certificate
-----BEGIN CERTIFICATE-----
MIID5zCCAs+gAwIBAgIJALnu1NlVpZ6zMA0GCSqGSIb3DQEBBQUAMHAxCzAJBgNV
BAYTAlVLMRYwFAYDVQQKDA1PcGVuU1NMIEdyb3VwMSIwIAYDVQQLDBlGT1IgVEVT
VElORyBQVVJQT1NFUyBPTkxZMSUwIwYDVQQDDBxPcGVuU1NMIFRlc3QgSW50ZXJt
ZWRpYXRlIENBMB4XDTExMTIwODE0MDE0OFoXDTIxMTAxNjE0MDE0OFowZDELMAkG
A1UEBhMCVUsxFjAUBgNVBAoMDU9wZW5TU0wgR3JvdXAxIjAgBgNVBAsMGUZPUiBU
RVNUSU5HIFBVUlBPU0VTIE9OTFkxGTAXBgNVBAMMEFRlc3QgU2VydmVyIENlcnQw
ggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQDzhPOSNtyyRspmeuUpxfNJ
KCLTuf7g3uQ4zu4iHOmRO5TQci+HhVlLZrHF9XqFXcIP0y4pWDbMSGuiorUmzmfi
R7bfSdI/+qIQt8KXRH6HNG1t8ou0VSvWId5TS5Dq/er5ODUr9OaaDva7EquHIcMv
vPQGuI+OEAcnleVCy9HVEIySrO4P3CNIicnGkwwiAud05yUAq/gPXBC1hTtmlPD7
TVcGVSEiJdvzqqlgv02qedGrkki6GY4S7GjZxrrf7Foc2EP+51LJzwLQx3/JfrCU
41NEWAsu/Sl0tQabXESN+zJ1pDqoZ3uHMgpQjeGiE0olr+YcsSW/tJmiU9OiAr8R
AgMBAAGjgY8wgYwwDAYDVR0TAQH/BAIwADAOBgNVHQ8BAf8EBAMCBeAwLAYJYIZI
AYb4QgENBB8WHU9wZW5TU0wgR2VuZXJhdGVkIENlcnRpZmljYXRlMB0GA1UdDgQW
BBSCvM8AABPR9zklmifnr9LvIBturDAfBgNVHSMEGDAWgBQ2w2yI55X+sL3szj49
hqshgYfa2jANBgkqhkiG9w0BAQUFAAOCAQEAqb1NV0B0/pbpK9Z4/bNjzPQLTRLK
WnSNm/Jh5v0GEUOE/Beg7GNjNrmeNmqxAlpqWz9qoeoFZax+QBpIZYjROU3TS3fp
yLsrnlr0CDQ5R7kCCDGa8dkXxemmpZZLbUCpW2Uoy8sAA4JjN9OtsZY7dvUXFgJ7
vVNTRnI01ghknbtD+2SxSQd3CWF6QhcRMAzZJ1z1cbbwGDDzfvGFPzJ+Sq+zEPds
xoVLLSetCiBc+40ZcDS5dV98h9XD7JMTQfxzA7mNGv73JoZJA6nFgj+ADSlJsY/t
JBv+z1iQRueoh9Qeee+ZbRifPouCB8FDx+AltvHTANdAq0t/K3o+pplMVA==
-----END CERTIFICATE-----
subject=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert

issuer=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA

---
No client certificate CA names sent
Peer signing digest: SHA256
Peer signature type: RSA-PSS
Server Temp Key: X25519, 253 bits
---
SSL handshake has read 1547 bytes and written 365 bytes
Verification error: unable to verify the first certificate
---
New, TLSv1.3, Cipher is TLS13-AES-128-GCM-SHA256
Server public key is 2048 bit
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
SSL-Session:
    Protocol  : TLSv1.3
    Cipher    : TLS13-AES-128-GCM-SHA256
    Session-ID:
    Session-ID-ctx:
    Master-Key: 000102030405060708090A0B0C0D0E0F101112131415161718191A1B1C1D1E1F
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1516017433
    Timeout   : 7200 (sec)
    Verify return code: 21 (unable to verify the first certificate)
    Extended master secret: no
---
 Record 2 (client -> server)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 53
  Inner content type: HANDSHAKE
140041907652352:error:142060B6:SSL routines:tls_process_key_update:not on record boundary:ssl/statem/statem_lib.c:622:
  Message type: Finished
  Message Length: 32

Forwarded packet length = 65

CONNECTION ESTABLISHED
Protocol version: TLSv1.3
Client cipher list: ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA384:DHE-RSA-AES256-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES256-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES256-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA:DHE-RSA-AES128-SHA:AES256-GCM-SHA384:AES128-GCM-SHA256:TLS13-AES-256-GCM-SHA384:TLS13-CHACHA20-POLY1305-SHA256:TLS13-AES-128-GCM-SHA256:AES256-SHA256:AES128-SHA256:AES256-SHA:AES128-SHA:TLS_EMPTY_RENEGOTIATION_INFO_SCSV
Received server packet
Ciphersuite: TLS13-AES-128-GCM-SHA256
Signature Algorithms: Packet length = 224
ECDSAProcessing flight 3
+SHA256:ECDSA+SHA384: Record 1ECDSA (server -> client)
+SHA512:Ed25519:RSA-PSS+SHA256:RSA-PSS+SHA384:RSA-PSS+SHA512:  Content type: APPLICATION DATA
RSA  Version: TLS1.2
+SHA256  Length: 219:
RSA+SHA384:RSA+SHA512:ECDSA+SHA224:ECDSA+SHA1:RSA+SHA224:RSA+SHA1:DSA+SHA224:DSA+SHA1:DSA+SHA256:DSA+SHA384:DSA+SHA512
No peer certificate
Supported Elliptic Groups:   Inner content type: HANDSHAKE
X25519:P-256:P-521:P-384
  Message type: NewSessionTicket
  Message Length: 198

Forwarded packet length = 225

Error on client end: Connection reset by peer
No progress made at /home/ed/OPC/openssl/test/../util/perl/TLSProxy/Proxy.pm line 348.
# Looks like you planned 18 tests but ran 17.
# Looks like your test exited with 104 just after 17.
CONNECTION CLOSED
   1 items in the session cache
   0 client connects (SSL_connect())
   0 client renegotiates (SSL_connect())
   0 client connects that finished
   1 server accepts (SSL_accept())
   0 server renegotiates (SSL_accept())
   1 server accepts that finished
   0 session cache hits
   0 session cache misses
   0 session cache timeouts
   0 callback cache hits
   0 cache full overflows (128 allowed)
Dubious, test returned 104 (wstat 26624, 0x6800)
Failed 1/18 subtests

Test Summary Report
-------------------
../test/recipes/70-test_sslrecords.t (Wstat: 26624 Tests: 17 Failed: 0)
  Non-zero exit status: 104
  Parse errors: Bad plan.  You planned 18 tests but ran 17.
Files=1, Tests=17, 11 wallclock secs ( 0.07 usr  0.00 sys +  0.23 cusr  0.14 csys =  0.44 CPU)
Result: FAIL
Makefile:168: recipe for target '_tests' failed
make[1]: Leaving directory '/home/ed/OPC/openssl'
Makefile:166: recipe for target 'tests' failed

intersting, where is the "DONE", did the client just crash?

bernd-edlinger · 2018-01-15T20:09:15Z

and a second fail after 1289 iterations:

    PSK identity hint: None
    SRP username: None
    Start Time: 1516019627
    Timeout   : 7200 (sec)
    Verify return code: 21 (unable to verify the first certificate)
    Extended master secret: yes
---
ok 4 - Fragmented alert records test
Server command: ../../util/shlib_wrap.sh ../../apps/openssl s_server -no_comp -rev -engine ossltest -accept 4443 -cert ../../apps/server.pem -cert2 ../../apps/server.pem -naccept 1 -cipher AES128-SHA:TLS13-AES-128-GCM-SHA256 -tls1_2
Proxy started on port 4453
Client command: echo test | ../../util/shlib_wrap.sh ../../apps/openssl s_client -engine ossltest -connect localhost:4453
engine "ossltest" set.
engine "ossltest" set.
Using default temp DH parameters
ACCEPT
Connection opened
Received client packet
Packet length = 301
Processing flight 0
 Record 1 (client -> server)
  Content type: HANDSHAKE
  Version: TLS1.0
  Length: 296
  Message type: ClientHello
  Message Length: 292
    Client Version:771
    Session ID Len:32
    Ciphersuite len:62
    Compression Method Len:1
    Extensions Len:157

Forwarded packet length = 46

Received server packet
Packet length = 1106
Processing flight 1
 Record 1 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 74
  Message type: ServerHello
  Message Length: 70
    Server Version:771
    Session ID Len:32
    Ciphersuite:47
    Compression Method:0
    Extensions Len:0
 Record 2 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 1013
  Message type: Certificate
  Message Length: 1009
    Certificate List Len:1006
    Certificate Len:1003
 Record 3 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 4
  Message type: ServerHelloDone
  Message Length: 0

Forwarded packet length = 1106

depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
verify error:num=20:unable to get local issuer certificate
verify return:1
depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
verify error:num=21:unable to verify the first certificate
verify return:1
Received client packet
Packet length = 342
Processing flight 2
 Record 1 (client -> server)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 262
  Message type: ClientKeyExchange
  Message Length: 258
 Record 2 (client -> server)
  Content type: CCS
  Version: TLS1.2
  Length: 1
 Record 3 (client -> server)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 64
  Message type: Finished
  Message Length: 12

Forwarded packet length = 342

CONNECTION ESTABLISHED
Received server packet
Packet length = 75
Protocol version: TLSv1.2
Processing flight 3
Client cipher list:  Record 1 (server -> client)
AES128-SHA
Ciphersuite: AES128-SHA
  Content type: CCS
  Version: TLS1.2
No peer certificate
  Length: 1
 Record 2 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 64
  Message type: Finished
  Message Length: 12

Forwarded packet length = 75

CONNECTED(00000003)
---
Certificate chain
 0 s:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
   i:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA
---
Server certificate
-----BEGIN CERTIFICATE-----
MIID5zCCAs+gAwIBAgIJALnu1NlVpZ6zMA0GCSqGSIb3DQEBBQUAMHAxCzAJBgNV
BAYTAlVLMRYwFAYDVQQKDA1PcGVuU1NMIEdyb3VwMSIwIAYDVQQLDBlGT1IgVEVT
VElORyBQVVJQT1NFUyBPTkxZMSUwIwYDVQQDDBxPcGVuU1NMIFRlc3QgSW50ZXJt
ZWRpYXRlIENBMB4XDTExMTIwODE0MDE0OFoXDTIxMTAxNjE0MDE0OFowZDELMAkG
A1UEBhMCVUsxFjAUBgNVBAoMDU9wZW5TU0wgR3JvdXAxIjAgBgNVBAsMGUZPUiBU
RVNUSU5HIFBVUlBPU0VTIE9OTFkxGTAXBgNVBAMMEFRlc3QgU2VydmVyIENlcnQw
ggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQDzhPOSNtyyRspmeuUpxfNJ
KCLTuf7g3uQ4zu4iHOmRO5TQci+HhVlLZrHF9XqFXcIP0y4pWDbMSGuiorUmzmfi
R7bfSdI/+qIQt8KXRH6HNG1t8ou0VSvWId5TS5Dq/er5ODUr9OaaDva7EquHIcMv
vPQGuI+OEAcnleVCy9HVEIySrO4P3CNIicnGkwwiAud05yUAq/gPXBC1hTtmlPD7
TVcGVSEiJdvzqqlgv02qedGrkki6GY4S7GjZxrrf7Foc2EP+51LJzwLQx3/JfrCU
41NEWAsu/Sl0tQabXESN+zJ1pDqoZ3uHMgpQjeGiE0olr+YcsSW/tJmiU9OiAr8R
AgMBAAGjgY8wgYwwDAYDVR0TAQH/BAIwADAOBgNVHQ8BAf8EBAMCBeAwLAYJYIZI
AYb4QgENBB8WHU9wZW5TU0wgR2VuZXJhdGVkIENlcnRpZmljYXRlMB0GA1UdDgQW
BBSCvM8AABPR9zklmifnr9LvIBturDAfBgNVHSMEGDAWgBQ2w2yI55X+sL3szj49
hqshgYfa2jANBgkqhkiG9w0BAQUFAAOCAQEAqb1NV0B0/pbpK9Z4/bNjzPQLTRLK
WnSNm/Jh5v0GEUOE/Beg7GNjNrmeNmqxAlpqWz9qoeoFZax+QBpIZYjROU3TS3fp
yLsrnlr0CDQ5R7kCCDGa8dkXxemmpZZLbUCpW2Uoy8sAA4JjN9OtsZY7dvUXFgJ7
vVNTRnI01ghknbtD+2SxSQd3CWF6QhcRMAzZJ1z1cbbwGDDzfvGFPzJ+Sq+zEPds
xoVLLSetCiBc+40ZcDS5dV98h9XD7JMTQfxzA7mNGv73JoZJA6nFgj+ADSlJsY/t
JBv+z1iQRueoh9Qeee+ZbRifPouCB8FDx+AltvHTANdAq0t/K3o+pplMVA==
-----END CERTIFICATE-----
subject=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert

issuer=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA

---
No client certificate CA names sent
---
SSL handshake has read 1181 bytes and written 643 bytes
Verification error: unable to verify the first certificate
---
New, SSLv3, Cipher is AES128-SHA
Server public key is 2048 bit
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
SSL-Session:
    Protocol  : TLSv1.2
    Cipher    : AES128-SHA
    Session-ID: 0102030405060708090A0B0C0D0E0F101112131415161718191A1B1C1D1E1F20
    Session-ID-ctx:
    Master-Key: 000102030405060708090A0B0C0D0E0F101112131415161718191A1B1C1D1E1F000102030405060708090A0B0C0D0E0F
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1516019627
    Timeout   : 7200 (sec)
    Verify return code: 21 (unable to verify the first certificate)
    Extended master secret: no
---
DONE
Received client packet
Packet length = 53
Processing flight 4
 Record 1 (client -> server)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 48
  [ENCRYPTED APPLICATION DATA]
  [test
]

Forwarded packet length = 53

Received server packet
Packet length = 53
Processing flight 5
 Record 1 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 48
  [ENCRYPTED APPLICATION DATA]
  [tset
]

Forwarded packet length = 53

Error on client end: Connection reset by peer
No progress made at /home/ed/OPC/openssl/test/../util/perl/TLSProxy/Proxy.pm line 348.
CONNECTION CLOSED
# Looks like you planned 18 tests but ran 4.
# Looks like your test exited with 104 just after 4.
   1 items in the session cache
   0 client connects (SSL_connect())
   0 client renegotiates (SSL_connect())
   0 client connects that finished
   1 server accepts (SSL_accept())
   0 server renegotiates (SSL_accept())
   1 server accepts that finished
   0 session cache hits
   0 session cache misses
   0 session cache timeouts
   0 callback cache hits
   0 cache full overflows (128 allowed)
Dubious, test returned 104 (wstat 26624, 0x6800)
Failed 14/18 subtests

Test Summary Report
-------------------
../test/recipes/70-test_sslrecords.t (Wstat: 26624 Tests: 4 Failed: 0)
  Non-zero exit status: 104
  Parse errors: Bad plan.  You planned 18 tests but ran 4.
Files=1, Tests=4, 10 wallclock secs ( 0.03 usr  0.00 sys +  0.10 cusr  0.03 csys =  0.16 CPU)
Result: FAIL
Makefile:168: recipe for target '_tests' failed
make[1]: Leaving directory '/home/ed/OPC/openssl'
Makefile:166: recipe for target 'tests' failed

This time there is a "DONE" followed by "[test", "[tset", No progress.
But the s_client shutdown patch is installed.

Theoretically possible that there was a packet loss, due to the RST
there can be no TCP retransmission.

The linux version is: Linux version 4.13.0-26-lowlatency (buildd@lgw01-amd64-031) (gcc version 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~~16.04.5)) #29~~16.04.2-Ubuntu SMP PREEMPT Tue Jan 9 22:52:31 UTC 2018

bernd-edlinger · 2018-01-15T20:19:37Z

While I wrote this, the very same test ran more than 10.000 iterations so I cannot reproduce any more.
I have no idea what was different in the morning.

levitte · 2018-01-15T22:47:07Z

Error on client end: Connection reset by peer
No progress made at /home/ed/OPC/openssl/test/../util/perl/TLSProxy/Proxy.pm line 348.

This made me realise that when the client end shuts down its writing end, this patch keeps the proxy connection to the server up and vice versa. It's incomplete in that respect, and then we end up in exactly the situation quoted there, there's nothing more coming from the client end, and the server end keeps hanging, waiting for more.

I'll fix

Whenever the client or the server would cut off communication, the proxy would immediately take down the proxy entirely. However, it's very possible that just because one side stopped communicating, the other side might still have a packet on its way. Since the proxy runs filters, and most of all checks for specific records to see if the communication was successful or not, it seems important that none of them are ignored. Therefore, recode the loop to simply ignore the channel where communication has stopped, but continue to receive data on the other until that one shuts down as well.

levitte · 2018-01-15T22:59:12Z

... thinking more about it, it's not entirely clear to me that doing so will make this change differ very much from the code before this change...

levitte · 2018-01-15T23:08:47Z

But anyway, fix committed, and the whole thing rebased on top of fresh master

bernd-edlinger · 2018-01-16T07:36:33Z

Well, yes, using the latest patch the behavior changed slightly, but still not ok:

    Verify return code: 21 (unable to verify the first certificate)
    Extended master secret: yes
---
Waiting for client process to close: 28871
ok 12 - Changed record version in TLS1.2
Server command: ../../util/shlib_wrap.sh ../../apps/openssl s_server -no_comp -rev -engine ossltest -accept 4443 -cert ../../apps/server.pem -cert2 ../../apps/server.pem -naccept 1 -cipher AES128-SHA:TLS13-AES-128-GCM-SHA256
Proxy started on port 4453
Client command: echo test | ../../util/shlib_wrap.sh ../../apps/openssl s_client -engine ossltest -connect localhost:4453
engine "ossltest" set.
engine "ossltest" set.
Connection opened
Using default temp DH parameters
ACCEPT
Received client packet
Packet length = 301
Processing flight 0
 Record 1 (client -> server)
  Content type: HANDSHAKE
  Version: TLS1.0
  Length: 296
  Message type: ClientHello
  Message Length: 292
    Client Version:771
    Session ID Len:32
    Ciphersuite len:62
    Compression Method Len:1
    Extensions Len:157

Forwarded packet length = 301

Received server packet
Packet length = 1543
Processing flight 1
 Record 1 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 122
  Message type: ServerHello
  Message Length: 118
    Server Version:771
    Session ID Len:32
    Ciphersuite:4865
    Compression Method:0
    Extensions Len:46
 Record 2 (server -> client)
  Content type: CCS
  Version: TLS1.2
  Length: 1
 Record 3 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 23
  Inner content type: HANDSHAKE
  Message type: EncryptedExtensions
  Message Length: 2
    Extensions Len:0
 Record 4 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 1033
  Inner content type: HANDSHAKE
  Message type: Certificate
  Message Length: 1012
    Context:
    Certificate List Len:1008
    Certificate Len:1003
    Extensions Len:0
 Record 5 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 281
  Inner content type: HANDSHAKE
  Message type: CertificateVerify
  Message Length: 260
    SigAlg:2052
    Signature Len:256
 Record 6 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 53
  Inner content type: HANDSHAKE
  Message type: Finished
  Message Length: 32

Forwarded packet length = 1547

depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
verify error:num=20:unable to get local issuer certificate
verify return:1
depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
verify error:num=21:unable to verify the first certificate
verify return:1
Received client packet
Packet length = 64
Processing flight 2
 Record 1 (client -> server)
  Content type: CCS
  Version: TLS1.2
  Length: 1
 Record 2 (client -> server)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 53
  Inner content type: HANDSHAKE
  Message type: Finished
  Message Length: 32
CONNECTED(00000003)
---
Certificate chain
 0 s:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
   i:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA
---
Server certificate
-----BEGIN CERTIFICATE-----
MIID5zCCAs+gAwIBAgIJALnu1NlVpZ6zMA0GCSqGSIb3DQEBBQUAMHAxCzAJBgNV
BAYTAlVLMRYwFAYDVQQKDA1PcGVuU1NMIEdyb3VwMSIwIAYDVQQLDBlGT1IgVEVT
VElORyBQVVJQT1NFUyBPTkxZMSUwIwYDVQQDDBxPcGVuU1NMIFRlc3QgSW50ZXJt
ZWRpYXRlIENBMB4XDTExMTIwODE0MDE0OFoXDTIxMTAxNjE0MDE0OFowZDELMAkG
A1UEBhMCVUsxFjAUBgNVBAoMDU9wZW5TU0wgR3JvdXAxIjAgBgNVBAsMGUZPUiBU
RVNUSU5HIFBVUlBPU0VTIE9OTFkxGTAXBgNVBAMMEFRlc3QgU2VydmVyIENlcnQw
ggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQDzhPOSNtyyRspmeuUpxfNJ
KCLTuf7g3uQ4zu4iHOmRO5TQci+HhVlLZrHF9XqFXcIP0y4pWDbMSGuiorUmzmfi
R7bfSdI/+qIQt8KXRH6HNG1t8ou0VSvWId5TS5Dq/er5ODUr9OaaDva7EquHIcMv
vPQGuI+OEAcnleVCy9HVEIySrO4P3CNIicnGkwwiAud05yUAq/gPXBC1hTtmlPD7
TVcGVSEiJdvzqqlgv02qedGrkki6GY4S7GjZxrrf7Foc2EP+51LJzwLQx3/JfrCU
41NEWAsu/Sl0tQabXESN+zJ1pDqoZ3uHMgpQjeGiE0olr+YcsSW/tJmiU9OiAr8R
AgMBAAGjgY8wgYwwDAYDVR0TAQH/BAIwADAOBgNVHQ8BAf8EBAMCBeAwLAYJYIZI
AYb4QgENBB8WHU9wZW5TU0wgR2VuZXJhdGVkIENlcnRpZmljYXRlMB0GA1UdDgQW
BBSCvM8AABPR9zklmifnr9LvIBturDAfBgNVHSMEGDAWgBQ2w2yI55X+sL3szj49
hqshgYfa2jANBgkqhkiG9w0BAQUFAAOCAQEAqb1NV0B0/pbpK9Z4/bNjzPQLTRLK
WnSNm/Jh5v0GEUOE/Beg7GNjNrmeNmqxAlpqWz9qoeoFZax+QBpIZYjROU3TS3fp
yLsrnlr0CDQ5R7kCCDGa8dkXxemmpZZLbUCpW2Uoy8sAA4JjN9OtsZY7dvUXFgJ7
vVNTRnI01ghknbtD+2SxSQd3CWF6QhcRMAzZJ1z1cbbwGDDzfvGFPzJ+Sq+zEPds
xoVLLSetCiBc+40ZcDS5dV98h9XD7JMTQfxzA7mNGv73JoZJA6nFgj+ADSlJsY/t
JBv+z1iQRueoh9Qeee+ZbRifPouCB8FDx+AltvHTANdAq0t/K3o+pplMVA==
-----END CERTIFICATE-----
subject=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert

issuer=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA

---
No client certificate CA names sent
Peer signing digest: SHA256
Peer signature type: RSA-PSS
Server Temp Key: X25519, 253 bits
---
SSL handshake has read 1547 bytes and written 365 bytes
Verification error: unable to verify the first certificate
---
New, TLSv1.3, Cipher is TLS13-AES-128-GCM-SHA256
Server public key is 2048 bit
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
SSL-Session:
    Protocol  : TLSv1.3
    Cipher    : TLS13-AES-128-GCM-SHA256
    Session-ID: 
    Session-ID-ctx: 
    Master-Key: 000102030405060708090A0B0C0D0E0F101112131415161718191A1B1C1D1E1F
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1516085814
    Timeout   : 7200 (sec)
    Verify return code: 21 (unable to verify the first certificate)
    Extended master secret: no
---

DONE
Forwarded packet length = 65

CONNECTION ESTABLISHED
Protocol version: TLSv1.3
Client cipher list: ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-CHACHA20-POLY1305Received server packet
:ECDHE-ECDSA-AES128-GCM-SHA256:Packet length = 224
ECDHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-SHA384:Processing flight 3
ECDHE-RSA-AES256-SHA384:DHE-RSA-AES256-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA256 Record 1:ECDHE-ECDSA-AES256-SHA (server -> client)
:ECDHE-RSA-AES256-SHA:DHE-RSA-AES256-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA:DHE-RSA-AES128-SHA:AES256-GCM-SHA384:AES128-GCM-SHA256:TLS13-AES-256-GCM-SHA384:TLS13-CHACHA20-POLY1305-SHA256:TLS13-AES-128-GCM-SHA256:AES256-SHA256:AES128-SHA256  Content type: APPLICATION DATA
:AES256-SHA  Version: TLS1.2
:AES128-SHA  Length: 219:TLS_EMPTY_RENEGOTIATION_INFO_SCSV

Ciphersuite: TLS13-AES-128-GCM-SHA256
Signature Algorithms: ECDSA+SHA256:ECDSA+SHA384  Inner content type: HANDSHAKE
  Message type: NewSessionTicket
  Message Length: 198
:ECDSA+SHA512:Ed25519:RSA-PSS+SHA256:RSA-PSS+SHA384:RSA-PSS+SHA512:RSA+SHA256:RSA
+SHA384:RSA+SHA512:ECDSA+SHA224:ECDSA+SHA1:RSA+SHA224:RSA+SHA1:DSA+SHA224:DSA+SHA1:DSA+SHA256:DSA+SHA384:DSA+SHA512
No peer certificate
Supported Elliptic Groups: X25519:P-256:Forwarded packet length = 225

P-521:P-384
Error on client end: Connection reset by peer
CONNECTION CLOSED
Server connection closed
Connection closed
Waiting for server process to close: 28894
   1 items in the session cache
   0 client connects (SSL_connect())
   0 client renegotiates (SSL_connect())
   0 client connects that finished
   1 server accepts (SSL_accept())
   0 server renegotiates (SSL_accept())
   1 server accepts that finished
   0 session cache hits
   0 session cache misses
   0 session cache timeouts
   0 callback cache hits
   0 cache full overflows (128 allowed)
Waiting for client process to close: 28895
not ok 13 - Changed record version in TLS1.3

#   Failed test 'Changed record version in TLS1.3'
#   at ../test/recipes/70-test_sslrecords.t line 156.

So maybe there is still a problem in the client shutdown sequence.
However each time I try to capture the local traffic with tcpdump the
problem stops to reproduce.

bernd-edlinger · 2018-01-16T08:15:54Z

Okay, I have been able to reproduce and capture the conversation with tcpdump:

Waiting for client process to close: 7179
ok 17 - Record not on boundary in TLS1.3 (Finished)
Proxy started on port 4453
Server command: ../../util/shlib_wrap.sh ../../apps/openssl s_server -no_comp -rev -engine ossltest -accept 4443 -cert ../../apps/server.pem -cert2 ../../apps/server.pem -naccept 1 -cipher AES128-SHA:TLS13-AES-128-GCM-SHA256
Client command: echo test | ../../util/shlib_wrap.sh ../../apps/openssl s_client -engine ossltest -connect localhost:4453
engine "ossltest" set.
Using default temp DH parameters
ACCEPT
engine "ossltest" set.
Connection opened
Received client packet
Packet length = 301
Processing flight 0
 Record 1 (client -> server)
  Content type: HANDSHAKE
  Version: TLS1.0
  Length: 296
  Message type: ClientHello
  Message Length: 292
    Client Version:771
    Session ID Len:32
    Ciphersuite len:62
    Compression Method Len:1
    Extensions Len:157

Forwarded packet length = 301

Received server packet
Packet length = 1543
Processing flight 1
 Record 1 (server -> client)
  Content type: HANDSHAKE
  Version: TLS1.2
  Length: 122
  Message type: ServerHello
  Message Length: 118
    Server Version:771
    Session ID Len:32
    Ciphersuite:4865
    Compression Method:0
    Extensions Len:46
 Record 2 (server -> client)
  Content type: CCS
  Version: TLS1.2
  Length: 1
 Record 3 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 23
  Inner content type: HANDSHAKE
  Message type: EncryptedExtensions
  Message Length: 2
    Extensions Len:0
 Record 4 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 1033
  Inner content type: HANDSHAKE
  Message type: Certificate
  Message Length: 1012
    Context:
    Certificate List Len:1008
    Certificate Len:1003
    Extensions Len:0
 Record 5 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 281
  Inner content type: HANDSHAKE
  Message type: CertificateVerify
  Message Length: 260
    SigAlg:2052
    Signature Len:256
 Record 6 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 53
  Inner content type: HANDSHAKE
  Message type: Finished
  Message Length: 32

Forwarded packet length = 1579

depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
verify error:num=20:unable to get local issuer certificate
verify return:1
depth=0 C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
verify error:num=21:unable to verify the first certificate
verify return:1
Received client packet
Packet length = 64
Processing flight 2
 Record 1 (client -> server)
  Content type: CCS
  Version: TLS1.2
  Length: 1
 Record 2 (client -> server)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 53
  Inner content type: HANDSHAKE
  Message type: Finished
  Message Length: 32

Forwarded packet length = 65

CONNECTED(00000003)
---
Certificate chain
 0 s:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert
   i:C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA
---
Server certificate
-----BEGIN CERTIFICATE-----
MIID5zCCAs+gAwIBAgIJALnu1NlVpZ6zMA0GCSqGSIb3DQEBBQUAMHAxCzAJBgNV
BAYTAlVLMRYwFAYDVQQKDA1PcGVuU1NMIEdyb3VwMSIwIAYDVQQLDBlGT1IgVEVT
VElORyBQVVJQT1NFUyBPTkxZMSUwIwYDVQQDDBxPcGVuU1NMIFRlc3QgSW50ZXJt
ZWRpYXRlIENBMB4XDTExMTIwODE0MDE0OFoXDTIxMTAxNjE0MDE0OFowZDELMAkG
A1UEBhMCVUsxFjAUBgNVBAoMDU9wZW5TU0wgR3JvdXAxIjAgBgNVBAsMGUZPUiBU
RVNUSU5HIFBVUlBPU0VTIE9OTFkxGTAXBgNVBAMMEFRlc3QgU2VydmVyIENlcnQw
ggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQDzhPOSNtyyRspmeuUpxfNJ
KCLTuf7g3uQ4zu4iHOmRO5TQci+HhVlLZrHF9XqFXcIP0y4pWDbMSGuiorUmzmfi
R7bfSdI/+qIQt8KXRH6HNG1t8ou0VSvWId5TS5Dq/er5ODUr9OaaDva7EquHIcMv
vPQGuI+OEAcnleVCy9HVEIySrO4P3CNIicnGkwwiAud05yUAq/gPXBC1hTtmlPD7
TVcGVSEiJdvzqqlgv02qedGrkki6GY4S7GjZxrrf7Foc2EP+51LJzwLQx3/JfrCU
41NEWAsu/Sl0tQabXESN+zJ1pDqoZ3uHMgpQjeGiE0olr+YcsSW/tJmiU9OiAr8R
AgMBAAGjgY8wgYwwDAYDVR0TAQH/BAIwADAOBgNVHQ8BAf8EBAMCBeAwLAYJYIZI
AYb4QgENBB8WHU9wZW5TU0wgR2VuZXJhdGVkIENlcnRpZmljYXRlMB0GA1UdDgQW
BBSCvM8AABPR9zklmifnr9LvIBturDAfBgNVHSMEGDAWgBQ2w2yI55X+sL3szj49
hqshgYfa2jANBgkqhkiG9w0BAQUFAAOCAQEAqb1NV0B0/pbpK9Z4/bNjzPQLTRLK
WnSNm/Jh5v0GEUOE/Beg7GNjNrmeNmqxAlpqWz9qoeoFZax+QBpIZYjROU3TS3fp
yLsrnlr0CDQ5R7kCCDGa8dkXxemmpZZLbUCpW2Uoy8sAA4JjN9OtsZY7dvUXFgJ7
vVNTRnI01ghknbtD+2SxSQd3CWF6QhcRMAzZJ1z1cbbwGDDzfvGFPzJ+Sq+zEPds
xoVLLSetCiBc+40ZcDS5dV98h9XD7JMTQfxzA7mNGv73JoZJA6nFgj+ADSlJsY/t
JBv+z1iQRueoh9Qeee+ZbRifPouCB8FDx+AltvHTANdAq0t/K3o+pplMVA==
-----END CERTIFICATE-----
subject=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = Test Server Cert

issuer=C = UK, O = OpenSSL Group, OU = FOR TESTING PURPOSES ONLY, CN = OpenSSL Test Intermediate CA

---
No client certificate CA names sent
Peer signing digest: SHA256
Peer signature type: RSA-PSS
Server Temp Key: X25519, 253 bits
---
SSL handshake has read 1547 bytes and written 365 bytes
Verification error: unable to verify the first certificate
---
New, TLSv1.3, Cipher is TLS13-AES-128-GCM-SHA256
Server public key is 2048 bit
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
SSL-Session:
    Protocol  : TLSv1.3
    Cipher    : TLS13-AES-128-GCM-SHA256
    Session-ID: 
    Session-ID-ctx: 
    Master-Key: 000102030405060708090A0B0C0D0E0F101112131415161718191A1B1C1D1E1F
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    Start Time: 1516087743
    Timeout   : 7200 (sec)
    Verify return code: 21 (unable to verify the first certificate)
    Extended master secret: no
---
140698170418944:error:142060B6:SSL routines:tls_process_key_update:not on record boundary:ssl/statem/statem_lib.c:622:
CONNECTION ESTABLISHED
Protocol version: TLSv1.3
Client cipher list: ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA384:DHE-RSA-AES256-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES256-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES256-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES128-SHA:DHE-RSA-AES128-SHA:AES256-GCM-SHA384:AES128-GCM-SHA256:TLS13-AES-256-GCM-SHA384:TLS13-CHACHA20-POLY1305-SHA256:TLS13-AES-128-GCM-SHA256:AES256-SHA256:AES128-SHA256:AES256-SHA:AES128-SHA:TLS_EMPTY_RENEGOTIATION_INFO_SCSV
Ciphersuite: TLS13-AES-128-GCM-SHA256
Signature Algorithms: ECDSA+SHA256:ECDSA+SHA384:ECDSA+SHA512:Ed25519:RSA-PSS+SHA256:RSA-PSS+SHA384:RSA-PSS+SHA512:RSA+SHA256:RSA+SHA384:RSA+SHA512:ECDSA+SHA224:ECDSA+SHA1:RSA+SHA224:RSA+SHA1:DSA+SHA224:DSA+SHA1:DSA+SHA256:DSA+SHA384:DSA+SHA512
No peer certificate
Supported Elliptic Groups: X25519:P-256:P-521:P-384
Received server packet
Packet length = 224
Processing flight 3
 Record 1 (server -> client)
  Content type: APPLICATION DATA
  Version: TLS1.2
  Length: 219
  Inner content type: HANDSHAKE
  Message type: NewSessionTicket
  Message Length: 198

Forwarded packet length = 225

Error on client end: Connection reset by peer
CONNECTION CLOSED
Server connection closed
Connection closed
Waiting for server process to close: 7203
   1 items in the session cache
   0 client connects (SSL_connect())
   0 client renegotiates (SSL_connect())
   0 client connects that finished
   1 server accepts (SSL_accept())
   0 server renegotiates (SSL_accept())
   1 server accepts that finished
   0 session cache hits
   0 session cache misses
   0 session cache timeouts
   0 callback cache hits
   0 cache full overflows (128 allowed)
Waiting for client process to close: 7205
not ok 18 - Record not on boundary in TLS1.3 (KeyUpdate)

#   Failed test 'Record not on boundary in TLS1.3 (KeyUpdate)'
#   at ../test/recipes/70-test_sslrecords.t line 199.
# Looks like you failed 1 test of 18.
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/18 subtests 

Test Summary Report
-------------------
../test/recipes/70-test_sslrecords.t (Wstat: 256 Tests: 18 Failed: 1)
  Failed test:  18
  Non-zero exit status: 1
Files=1, Tests=18,  1 wallclock secs ( 0.08 usr  0.00 sys +  0.32 cusr  0.13 csys =  0.53 CPU)
Result: FAIL
Makefile:168: recipe for target '_tests' failed
make[1]: Leaving directory '/home/ed/OPC/openssl'
Makefile:166: recipe for target 'tests' failed

The capture shows the problem starts in the server:
failed_test.pcap.zip

Funny, there is first a RST and then something like an ALERT from the server.

Content Type: Application Data (23)
Version: TLS 1.2 (0x0303)
Length: 19
Encrypted Application Data: 020a1500000000000000000000000000000000

And why is the proxy adding one trailing byte to each packet?

bernd-edlinger · 2018-01-16T09:00:30Z

Funny, there is first a RST and then something like an ALERT from the server.

Hmm, this was actually from the client.

levitte · 2018-01-16T12:10:17Z

And why is the proxy adding one trailing byte to each packet?

Not sure what you mean there...

bernd-edlinger · 2018-01-16T12:37:09Z

I mean in the capture file packet 15 is from server -> proxy
packet 16 is the same from proxy -> client

15	0.008912	127.0.0.1	127.0.0.1	TLSv1.2	130	Change Cipher Spec, Application Data
Transmission Control Protocol, Src Port: 53718, Dst Port: 4453, Seq: 302, Ack: 1580, Len: 64
0000   00 00 00 00 00 00 00 00 00 00 00 00 08 00 45 00
0010   00 74 08 c6 40 00 40 06 33 bc 7f 00 00 01 7f 00
0020   00 01 d1 d6 11 65 40 c9 0b 1d a5 4c 27 3c 80 18
0030   05 55 fe 68 00 00 01 01 08 0a 42 5b 92 bb 42 5b
0040   92 b9 14 03 03 00 01 01 17 03 03 00 35 14 00 00
0050   20 00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e
0060   0f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e
0070   1f 16 00 00 00 00 00 00 00 00 00 00 00 00 00 00
0080   00 00
16	0.009401	127.0.0.1	127.0.0.1	TLSv1.2	131	Change Cipher Spec, Application Data
Transmission Control Protocol, Src Port: 40594, Dst Port: 4443, Seq: 302, Ack: 1544, Len: 65
0000   00 00 00 00 00 00 00 00 00 00 00 00 08 00 45 00
0010   00 75 ba 66 40 00 40 06 82 1a 7f 00 00 01 7f 00
0020   00 01 9e 92 11 5b c2 e5 bc 7a 06 c9 d1 3f 80 18
0030   05 55 fe 69 00 00 01 01 08 0a 42 5b 92 bc 42 5b
0040   92 b8 14 03 03 00 01 01 17 03 03 00 36 14 00 00
0050   20 00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e
0060   0f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e
0070   1f 16 00 00 00 00 00 00 00 00 00 00 00 00 00 00
0080   00 00 16

16 what is that?

mattcaswell · 2018-02-14T17:41:33Z

16 what is that?

See #5370.

So what is happening with this PR now?

levitte · 2018-02-14T17:54:12Z

So what is happening with this PR now?

Dunno, really... with all the other changes we made, it seems this one isn't needed any more, possibly because it didn't address the actual issue. I'd say that's grounds for just closing it, right?

bernd-edlinger · 2018-02-14T19:10:01Z

There capture in my previous comment shows a sort of race condition,
but it happens extremely rarely:

tcpdump -r failed_test.pcap tcp port 4453
reading from file failed_test.pcap, link-type EN10MB (Ethernet)
08:29:03.329982 IP localhost.53718 > localhost.4453: Flags [S], seq 1086917103, win 43690, options [mss 65495,sackOK,TS val 1113297587 ecr 0,nop,wscale 7], length 0
08:29:03.329994 IP localhost.4453 > localhost.53718: Flags [S.], seq 2773229840, ack 1086917104, win 43690, options [mss 65495,sackOK,TS val 1113297587 ecr 1113297587,nop,wscale 7], length 0
08:29:03.330007 IP localhost.53718 > localhost.4453: Flags [.], ack 1, win 342, options [nop,nop,TS val 1113297587 ecr 1113297587], length 0
08:29:03.331305 IP localhost.53718 > localhost.4453: Flags [P.], seq 1:302, ack 1, win 342, options [nop,nop,TS val 1113297588 ecr 1113297587], length 301
08:29:03.331313 IP localhost.4453 > localhost.53718: Flags [.], ack 302, win 350, options [nop,nop,TS val 1113297588 ecr 1113297588], length 0
08:29:03.336799 IP localhost.4453 > localhost.53718: Flags [P.], seq 1:1580, ack 302, win 350, options [nop,nop,TS val 1113297593 ecr 1113297588], length 1579
08:29:03.338167 IP localhost.53718 > localhost.4453: Flags [.], ack 1580, win 1365, options [nop,nop,TS val 1113297595 ecr 1113297593], length 0
08:29:03.338894 IP localhost.53718 > localhost.4453: Flags [P.], seq 302:366, ack 1580, win 1365, options [nop,nop,TS val 1113297595 ecr 1113297593], length 64
08:29:03.340577 IP localhost.4453 > localhost.53718: Flags [P.], seq 1580:1805, ack 366, win 350, options [nop,nop,TS val 1113297597 ecr 1113297595], length 225
08:29:03.340596 IP localhost.53718 > localhost.4453: Flags [R], seq 1086917469, win 0, length 0
08:29:03.340636 IP localhost.53718 > localhost.4453: Flags [FP.], seq 366:390, ack 1580, win 1365, options [nop,nop,TS val 1113297597 ecr 1113297593], length 24
08:29:03.340646 IP localhost.4453 > localhost.53718: Flags [R], seq 2773231420, win 0, length 0

I think the packets arrive not in the same order as they are sent to the loopback device.
the packet at 08:29:03.340636 arrives about 50 microseconds too late,
and the packet at 08:29:03.340577 arrives after the shutdown and causes
the RST packet at 08:29:03.340596, and the test fails.

I think this happens way too rarely to be worth the effort.

If we want to fix that really, we would not only forward the FIN packets
in both directions as this PR does, but have modify both s_client and
s_server to do a two-phase shutdown (send first FIN, wait for data,
close socket when FIN recieved).
Or maybe do a full two-phase TLS-shutdown.

mattcaswell · 2018-03-21T11:47:06Z

So I think the conclusion from the above is that this should be closed.

levitte added branch: master Applies to master branch 1.1.0 labels Jan 12, 2018

levitte requested review from bernd-edlinger, kaduk and mattcaswell January 12, 2018 20:26

bernd-edlinger reviewed Jan 12, 2018

View reviewed changes

util/perl/TLSProxy/Proxy.pm Outdated

Copy link

Member

bernd-edlinger Jan 12, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think here we need to disable SIGPIPE with:
SIG{PIPE} = "IGNORE";

bernd-edlinger reviewed Jan 12, 2018

View reviewed changes

bernd-edlinger mentioned this pull request Jan 13, 2018

Catch SIGPIPE in TLSProxy::Proxy::clientstart #5071

Closed

levitte force-pushed the fix-TLSProxy-20180112 branch from c288c60 to d7f2467 Compare January 14, 2018 13:52

bernd-edlinger approved these changes Jan 15, 2018

View reviewed changes

levitte closed this Jan 15, 2018

levitte reopened this Jan 15, 2018

fixup! In TLSProxy::Proxy::clientstart(), don't cut off all com at once

878cd18

levitte force-pushed the fix-TLSProxy-20180112 branch from d7f2467 to 878cd18 Compare January 15, 2018 23:08

mattcaswell added this to the 1.1.1 milestone Jan 24, 2018

mattcaswell mentioned this pull request Feb 14, 2018

Remove a spurious TLSProxy byte in TLSv1.3 #5370

Closed

2 tasks

mattcaswell closed this Mar 21, 2018

bernd-edlinger mentioned this pull request Mar 31, 2018

TLSProxy using random ports #5805

Closed

Uh oh!

Conversation

levitte commented Jan 12, 2018

Uh oh!

levitte commented Jan 12, 2018

Uh oh!

bernd-edlinger commented Jan 12, 2018

Uh oh!

bernd-edlinger Jan 12, 2018

Choose a reason for hiding this comment

Uh oh!

levitte commented Jan 12, 2018

Uh oh!

levitte commented Jan 12, 2018

Uh oh!

levitte commented Jan 12, 2018

Uh oh!

bernd-edlinger Jan 12, 2018

Choose a reason for hiding this comment

Uh oh!

levitte Jan 12, 2018

Choose a reason for hiding this comment

Uh oh!

bernd-edlinger Jan 12, 2018

Choose a reason for hiding this comment

Uh oh!

levitte Jan 12, 2018

Choose a reason for hiding this comment

Uh oh!

bernd-edlinger Jan 12, 2018

Choose a reason for hiding this comment

Uh oh!

bernd-edlinger commented Jan 12, 2018

Uh oh!

levitte commented Jan 12, 2018

Uh oh!

kaduk commented Jan 12, 2018

Uh oh!

bernd-edlinger commented Jan 12, 2018

Uh oh!

kaduk commented Jan 12, 2018

Uh oh!

levitte commented Jan 12, 2018

Uh oh!

bernd-edlinger commented Jan 12, 2018

Uh oh!

levitte commented Jan 12, 2018

Uh oh!

bernd-edlinger commented Jan 12, 2018

Uh oh!

kaduk commented Jan 12, 2018

Uh oh!

bernd-edlinger commented Jan 13, 2018

Uh oh!

levitte commented Jan 13, 2018

Uh oh!

levitte commented Jan 13, 2018

Uh oh!

bernd-edlinger commented Jan 15, 2018

Uh oh!

bernd-edlinger left a comment

Choose a reason for hiding this comment

Uh oh!

bernd-edlinger commented Jan 15, 2018

Uh oh!

levitte commented Jan 15, 2018

Uh oh!

levitte commented Jan 15, 2018

Uh oh!

bernd-edlinger commented Jan 15, 2018

Uh oh!

bernd-edlinger commented Jan 15, 2018

Uh oh!

bernd-edlinger commented Jan 15, 2018

Uh oh!

bernd-edlinger commented Jan 15, 2018

Uh oh!

levitte commented Jan 15, 2018

Uh oh!

levitte commented Jan 15, 2018