You're welcome. I don't like unsolved mysteries, and since I have a solid reproducer, thought I should do what I can.This is quite cool, thank you.
Some more. I looked into building on Windows, but the doc says one needs commercial tools; I'm not going to buy them for this.
However, I got verb 9 traces from the client and server side of a failure.They're a bit too large to post here, but I can provide the full traces off-list.
I haven't backtracked to understanding what is being sent. Perhaps one of you has the magic decoder for the data in the messages...
Here's a summary of what I see that seems interesting:
Server:
SSL state: Read client hello B
Write server hello A
Write certificate a
Write key exchange A
Write certificate request A
Flush data
This is the server sending the data that triggers the error, starting
with the preceding read (that presumably triggers it):
Wed Apr 23 09:26:25 2014 us=505743 GET INST BY REAL: 192.168.148.191:1194 [succeeded] Wed Apr 23 09:26:25 2014 us=507179 192.168.148.191:1194 UDP READ [50] from [AF_INET]192.168.148.191:1194: P_ACK_V1 kid=0 sid=87209bbf d7d12aeb tls_hmac=03a350ad c3c8bd68 06aacaa0 148a74fd b7731036 pid=[ #38 / time = (1398259583) Wed Apr 23 09:26:23 2014 ] [ 30 sid=adda013b a627c847 ] Wed Apr 23 09:26:25 2014 us=508665 192.168.148.191:1194 TLS: control channel, op=P_ACK_V1, IP=[AF_INET]192.168.148.191:1194 Wed Apr 23 09:26:25 2014 us=510704 192.168.148.191:1194 TLS: initial packet test, i=0 state=S_START, mysid=95747581 daf31aa7, rec-sid=87209bbf d7d12aeb, rec-ip=[AF_INET]192.168.148.191:1194, stored-sid=65fbeaf3 0672d359, stored-ip=[AF_INET]192.168.148.191:1194 Wed Apr 23 09:26:25 2014 us=511162 192.168.148.191:1194 TLS: initial packet test, i=1 state=S_START, mysid=adda013b a627c847, rec-sid=87209bbf d7d12aeb, rec-ip=[AF_INET]192.168.148.191:1194, stored-sid=87209bbf d7d12aeb, stored-ip=[AF_INET]192.168.148.191:1194 Wed Apr 23 09:26:25 2014 us=512181 192.168.148.191:1194 TLS: found match, session[1], sid=87209bbf d7d12aeb Wed Apr 23 09:26:25 2014 us=513617 192.168.148.191:1194 PID_TEST [0] [TLS_AUTH-0] [0000000001111111111111111122222222222] 1398259583:37 1398259583:38 t=1398259585[0] r=[-2,64,15,0,1] sl=[27,37,64,272] Wed Apr 23 09:26:25 2014 us=514591 192.168.148.191:1194 TLS: received control channel packet s#=1 sid=87209bbf d7d12aeb Wed Apr 23 09:26:25 2014 us=515784 192.168.148.191:1194 ACK received for pid 30, deleting from send buffer Wed Apr 23 09:26:25 2014 us=516298 192.168.148.191:1194 TLS: tls_multi_process: i=0 state=S_START, mysid=95747581 daf31aa7, stored-sid=65fbeaf3 0672d359, stored-ip=[AF_INET]192.168.148.191:1194 Wed Apr 23 09:26:25 2014 us=517260 192.168.148.191:1194 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=604800 Wed Apr 23 09:26:25 2014 us=518489 192.168.148.191:1194 ACK reliable_can_send active=1 current=0 : [35] 34 Wed Apr 23 09:26:25 2014 us=518920 192.168.148.191:1194 ACK reliable_send_timeout 1 [35] 34 Wed Apr 23 09:26:25 2014 us=519836 192.168.148.191:1194 TLS: tls_process: timeout set to 1 Wed Apr 23 09:26:25 2014 us=521129 192.168.148.191:1194 TLS: tls_multi_process: i=1 state=S_START, mysid=adda013b a627c847, stored-sid=87209bbf d7d12aeb, stored-ip=[AF_INET]192.168.148.191:1194 Wed Apr 23 09:26:25 2014 us=522055 192.168.148.191:1194 TLS: tls_process: chg=0 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=1 Wed Apr 23 09:26:25 2014 us=523328 192.168.148.191:1194 ACK reliable_can_send active=3 current=0 : [34] 33 31 32 Wed Apr 23 09:26:25 2014 us=523743 192.168.148.191:1194 BIO read tls_read_ciphertext 95 bytes Wed Apr 23 09:26:25 2014 us=524649 192.168.148.191:1194 ACK mark active outgoing ID 34 Wed Apr 23 09:26:25 2014 us=525799 192.168.148.191:1194 Outgoing Ciphertext -> Reliable Wed Apr 23 09:26:25 2014 us=526116 192.168.148.191:1194 TLS: tls_process: chg=1 ks=S_START lame=S_UNDEF to_link->len=0 wakeup=1 Wed Apr 23 09:26:25 2014 us=527049 192.168.148.191:1194 ACK reliable_can_send active=4 current=1 : [35] 33 34 31 32 Wed Apr 23 09:26:25 2014 us=528217 192.168.148.191:1194 ACK reliable_send ID 34 (size=99 to=5)
Wed Apr 23 09:26:25 2014 us=528542 192.168.148.191:1194 Reliable -> TCP/UDPWed Apr 23 09:26:25 2014 us=529436 192.168.148.191:1194 ACK reliable_send_timeout 2 [35] 33 34 31 32 Wed Apr 23 09:26:25 2014 us=530612 192.168.148.191:1194 TLS: tls_process: timeout set to 1 Wed Apr 23 09:26:25 2014 us=531584 192.168.148.191:1194 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[AF_UNSPEC]
Wed Apr 23 09:26:25 2014 us=532955 PO_CTL rwflags=0x0002 ev=5 arg=0x0009377c Wed Apr 23 09:26:25 2014 us=533939 PO_CTL rwflags=0x0000 ev=4 arg=0x000936f0 Wed Apr 23 09:26:25 2014 us=535162 PO_CTL rwflags=0x0001 ev=3 arg=0x000936f4 Wed Apr 23 09:26:25 2014 us=536073 I/O WAIT Tr|Tw|Sr|SW [1/14229]Wed Apr 23 09:26:25 2014 us=537294 PO_WAIT[0,0] fd=5 rev=0x00000004 rwflags=0x0002 arg=0x0009377c
Wed Apr 23 09:26:25 2014 us=538184 event_wait returned 1 Wed Apr 23 09:26:25 2014 us=539337 I/O WAIT status=0x0002Wed Apr 23 09:26:25 2014 us=540187 192.168.148.191:1194 UDP WRITE [137] to [AF_INET]192.168.148.191:1194: P_CONTROL_V1 kid=0 sid=adda013b a627c847 tls_hmac=69167505 34ab0aa4 2ade5c8e d9ef05b6 5ac2dfab pid=[ #40 / time = (1398259583) Wed Apr 23 09:26:23 2014 ] [ ] pid=34 DATA 37060355 040b1330 436f7079 72696768 74202863 29203230 3035206c 6974747[more...]
Client: UDPv4 read 142 VERIFY OK SERVER...(certificate) Write 50 ack. 5 pairs of read[142] controlv1, write[50] ack Read [137], error Here is the read that delivers the data that triggers the error: Wed Apr 23 09:26:20 2014 us=903142 UDPv4 read returned 137Wed Apr 23 09:26:20 2014 us=903142 UDPv4 READ [137] from [AF_INET]192.168.148.43:1194: P_CONTROL_V1 kid=0 sid=95747581 daf31aa7 tls_hmac=15534b4c 83ce2907 cffe8c48 4be9370f ccb726dd pid=[ #40 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ ] pid=34 DATA 37060355 040b1330 436f7079 72696768 74202863 29203230 3035206c 6974747[more...] Wed Apr 23 09:26:20 2014 us=923171 TLS_ERROR: BIO read tls_read_plaintext error: error:04066083:rsa routines:RSA_EAY_PRIVATE_ENCRYPT:invalid message length: error:14099006:SSL routines:SSL3_SEND_CLIENT_VERIFY:EVP lib Wed Apr 23 09:26:20 2014 us=923171 TLS Error: TLS object -> incoming plaintext read error
Wed Apr 23 09:26:20 2014 us=923171 TLS Error: TLS handshake failedHere are the 5 message pairs between the Cert OK and the failing message. I removed the noise messages (byte counts, event wait status) from the log. The writes all appear to be ACKs.
Wed Apr 23 09:26:20 2014 us=652782 UDPv4 WRITE [50] to [AF_INET]192.168.148.43:1194: P_ACK_V1 kid=0 sid=65fbeaf3 0672d359 tls_hmac=1d970787 6387a112 fa241879 3429db57 a5b68435 pid=[ #36 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ 28 sid=95747581 daf31aa7 ]
Wed Apr 23 09:26:20 2014 us=672811 UDPv4 READ [142] from [AF_INET]192.168.148.43:1194: P_CONTROL_V1 kid=0 sid=95747581 daf31aa7 tls_hmac=5a711521 a62527f7 50dc3d1a f047f0ee 17094d8d pid=[ #35 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ ] pid=29 DATA d2746c2a f024d185 051b2752 aca668b6 7f9f22de a4f25616 b6aafc52 b6bf9b8[more...]
Wed Apr 23 09:26:20 2014 us=702854 UDPv4 WRITE [50] to [AF_INET]192.168.148.43:1194: P_ACK_V1 kid=0 sid=65fbeaf3 0672d359 tls_hmac=43cd31d4 29be233d fb064ab0 6b98b0eb 244122b8 pid=[ #37 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ 29 sid=95747581 daf31aa7 ]
Wed Apr 23 09:26:20 2014 us=722883 UDPv4 READ [142] from [AF_INET]192.168.148.43:1194: P_CONTROL_V1 kid=0 sid=95747581 daf31aa7 tls_hmac=1f005f28 be069203 07814239 15429d20 7ffb7d72 pid=[ #36 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ ] pid=30 DATA dac5cf1a 4cf3d888 09ea429e cba8679e 138eacca 31cedde9 2585a3db f636c68[more...]
Wed Apr 23 09:26:20 2014 us=742912 UDPv4 WRITE [50] to [AF_INET]192.168.148.43:1194: P_ACK_V1 kid=0 sid=65fbeaf3 0672d359 tls_hmac=44239672 0d62fee0 32523b61 749d4f16 04121cac pid=[ #38 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ 30 sid=95747581 daf31aa7 ]
Wed Apr 23 09:26:20 2014 us=772955 UDPv4 READ [142] from [AF_INET]192.168.148.43:1194: P_CONTROL_V1 kid=0 sid=95747581 daf31aa7 tls_hmac=9f713546 9c9bbfb0 7719bc2e 543dd209 394cf6ff pid=[ #37 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ ] pid=31 DATA 318afd4a 455bde09 7c2107a6 6ef02d90 47b391b7 7c760a08 d3060100 80dff9e[more...]
Wed Apr 23 09:26:20 2014 us=792984 UDPv4 WRITE [50] to [AF_INET]192.168.148.43:1194: P_ACK_V1 kid=0 sid=65fbeaf3 0672d359 tls_hmac=5dcca51f 2b311a49 48203039 62e50c3e a3d071a3 pid=[ #39 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ 31 sid=95747581 daf31aa7 ]
Wed Apr 23 09:26:20 2014 us=813012 UDPv4 READ [142] from [AF_INET]192.168.148.43:1194: P_CONTROL_V1 kid=0 sid=95747581 daf31aa7 tls_hmac=ae03c703 d69f77d6 816e68c6 3632fd45 724543cc pid=[ #38 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ ] pid=32 DATA 1e4d6356 d5e2df84 e4318776 e0351663 08da96c4 fec9cb83 50fef6db f2e28e1[more...]
Wed Apr 23 09:26:20 2014 us=843056 UDPv4 WRITE [50] to [AF_INET]192.168.148.43:1194: P_ACK_V1 kid=0 sid=65fbeaf3 0672d359 tls_hmac=3b13fabd 17abc8d3 d1d94c4d 395688e3 76033fdd pid=[ #40 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ 32 sid=95747581 daf31aa7 ]
Wed Apr 23 09:26:20 2014 us=863084 UDPv4 READ [142] from [AF_INET]192.168.148.43:1194: P_CONTROL_V1 kid=0 sid=95747581 daf31aa7 tls_hmac=b9269cd2 47b74a73 c43b5161 30517429 56161792 pid=[ #39 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ ] pid=33 DATA 02020203 010100b7 00b53081 b2311d30 1b060355 04031314 6c697474 732e6e6[more...]
Wed Apr 23 09:26:20 2014 us=883113 UDPv4 WRITE [50] to [AF_INET]192.168.148.43:1194: P_ACK_V1 kid=0 sid=65fbeaf3 0672d359 tls_hmac=51cd68bb cd99bd7e 4988f67d 6c385535 7b4dfa06 pid=[ #41 / time = (1398259578) Wed Apr 23 09:26:18 2014 ] [ 33 sid=95747581 daf31aa7 ]
Hope this helps. Timothe Litt ACM Distinguished Engineer -------------------------- This communication may not represent the ACM or my employer's views, if any, on the matters discussed. On 23-Apr-14 04:10, Gert Doering wrote:
Hi, On Tue, Apr 22, 2014 at 10:58:22PM -0400, Timothe Litt wrote:It does not appear to be the negotiation, rather it's TLS1.2.This is quite cool, thank you. (I'm not enough of a crypto geek to make real sense out of it, but it's quite useful to understand where it is failing, and I appreciate that you took the time to dig into it) Steffan, Arne, any ideas? gert
smime.p7s
Description: S/MIME Cryptographic Signature
