[gnutls-help] DTLS and retransmission and reordering

Wed Apr 10 00:27:06 CEST 2013

according to rfc4347 section 3.2.2 gnutls should be robust against reordering 
during handshaking by queuing packages and process them in the right order.

regards
joke

On Tuesday 09 April 2013 22:02:25 you wrote:
> hi,
> 
> i'm not use but a have to questions regarding the dtls implementation.
> 
> first of all i'm using the multiple threads and every thread can receive
> packets from the udp socket. each thread calls the receive() and the packet
> is copied into the correct gnutls of the correct session.
> 
> if i'm using only one thread it's more or less guarantied gnutls receives
> the data in the correct order. reodering of udp packets is still possible
> though. everything works fine and the handshake completes.
> 
> but if the packet are received out of order gnutls doesn't seem to write all
> the outgoing packet. check the log "Discarded duplicate message[0]:
> Handshake”.
> 
> since udp/ip doesn't use sequence numbers reordering can always be an issue
> and gnutls should handle it during the handshake procedure. even if the
> reordering is caused by threads.
> 
> and other problem seems to be a problem with the dtls retransmission. each
> side doesn't seem to honer the timeout. if the timer run out both side just
> try to pull data with doesn't work and causes a EGAIN. which
> 
> 
> regards
> joke
> 
> |<7>| READ: Got 208 bytes from 0x7f618c004cc0
> |<7>| READ: read 208 bytes from 0x7f618c004cc0
> |<7>| RB: Have 0 bytes into buffer. Adding 208 bytes.
> |<7>| RB: Requested 13 bytes
> |<4>| REC[0x7f618c004ea0]: SSL 254.255 Handshake packet received. Epoch 0,
> 
> length: 195
> 
> |<4>| REC[0x7f618c004ea0]: Expected Packet Handshake(22)
> |<4>| REC[0x7f618c004ea0]: Received Packet Handshake(22) with length: 195
> 
> |<4>| REC[0x7f618c004ea0]: Decrypted Packet[0.1] Handshake(22) with length:
> 195
> 
> |<6>| BUF[REC]: Inserted 195 bytes of Data(22)
> |<3>| HSK[0x7f618c004ea0]: CLIENT HELLO (1) was received. Length 183[183],
> 
> frag offset 0, frag length: 183, sequence: 1
> 
> |<3>| HSK[0x7f618c004ea0]: Client's version: 254.255
> |<2>| ASSERT: /libgnutls/lib/gnutls_db.c:278
> |<3>| EXT[0x7f618c004ea0]: Found extension 'STATUS REQUEST/5'
> |<3>| EXT[0x7f618c004ea0]: Found extension 'CERT TYPE/9'
> |<3>| EXT[0x7f618c004ea0]: Found extension 'SAFE RENEGOTIATION/65281'
> |<3>| EXT[0x7f618c004ea0]: Found extension 'HEARTBEAT/15'
> |<3>| EXT[0x7f618c004ea0]: Found extension 'SESSION TICKET/35'
> |<3>| EXT[0x7f618c004ea0]: Found extension 'SUPPORTED ECC/10'
> |<3>| EXT[0x7f618c004ea0]: Found extension 'SUPPORTED ECC POINT FORMATS/11'
> |<3>| EXT[0x7f618c004ea0]: Found extension 'STATUS REQUEST/5'
> |<3>| EXT[0x7f618c004ea0]: Found extension 'CERT TYPE/9'
> |<3>| EXT[0x7f618c004ea0]: Parsing extension 'SAFE RENEGOTIATION/65281' (1
> 
> bytes)
> 
> |<3>| EXT[0x7f618c004ea0]: Found extension 'HEARTBEAT/15'
> |<3>| EXT[0x7f618c004ea0]: Parsing extension 'SESSION TICKET/35' (0 bytes)
> |<3>| EXT[0x7f618c004ea0]: Found extension 'SUPPORTED ECC/10'
> |<3>| EXT[0x7f618c004ea0]: Found extension 'SUPPORTED ECC POINT FORMATS/11'
> |<3>| EXT[0x7f618c004ea0]: Parsing extension 'STATUS REQUEST/5' (5 bytes)
> |<3>| EXT[0x7f618c004ea0]: Parsing extension 'CERT TYPE/9' (2 bytes)
> |<3>| HSK[0x7f618c004ea0]: Selected certificate type OPENPGP (2)
> |<3>| EXT[0x7f618c004ea0]: Found extension 'SAFE RENEGOTIATION/65281'
> |<3>| EXT[0x7f618c004ea0]: Parsing extension 'HEARTBEAT/15' (1 bytes)
> |<2>| HB: received parameter 1 (1 bytes)
> |<3>| EXT[0x7f618c004ea0]: Found extension 'SESSION TICKET/35'
> |<3>| EXT[0x7f618c004ea0]: Parsing extension 'SUPPORTED ECC/10' (12 bytes)
> |<3>| HSK[0x7f618c004ea0]: Selected ECC curve SECP192R1 (5)
> |<3>| EXT[0x7f618c004ea0]: Parsing extension 'SUPPORTED ECC POINT
> |FORMATS/11'
> (2 bytes)
> 
> |<2>| ASSERT: /libgnutls/lib/ext/server_name.c:300
> |<3>| HSK[0x7f618c004ea0]: Requested PK algorithm: EC (4) -- ctype: OPENPGP
> 
> (2)
> 
> |<3>| HSK[0x7f618c004ea0]: certificate[0] PK algorithm: RSA (1) - ctype:
> OPENPGP (2)
> 
> |<3>| HSK[0x7f618c004ea0]: Requested PK algorithm: EC (4) -- ctype: OPENPGP
> 
> (2)
> 
> |<3>| HSK[0x7f618c004ea0]: certificate[0] PK algorithm: RSA (1) - ctype:
> OPENPGP (2)
> 
> |<3>| HSK[0x7f618c004ea0]: Requested PK algorithm: EC (4) -- ctype: OPENPGP
> 
> (2)
> 
> |<3>| HSK[0x7f618c004ea0]: certificate[0] PK algorithm: RSA (1) - ctype:
> OPENPGP (2)
> 
> |<3>| HSK[0x7f618c004ea0]: Requested PK algorithm: EC (4) -- ctype: OPENPGP
> 
> (2)
> 
> |<3>| HSK[0x7f618c004ea0]: certificate[0] PK algorithm: RSA (1) - ctype:
> OPENPGP (2)
> 
> |<3>| HSK[0x7f618c004ea0]: Requested PK algorithm: EC (4) -- ctype: OPENPGP
> 
> (2)
> 
> |<3>| HSK[0x7f618c004ea0]: certificate[0] PK algorithm: RSA (1) - ctype:
> OPENPGP (2)
> 
> |<3>| HSK[0x7f618c004ea0]: Requested PK algorithm: EC (4) -- ctype: OPENPGP
> 
> (2)
> 
> |<3>| HSK[0x7f618c004ea0]: certificate[0] PK algorithm: RSA (1) - ctype:
> OPENPGP (2)
> 
> |<3>| HSK[0x7f618c004ea0]: Requested PK algorithm: EC (4) -- ctype: OPENPGP
> 
> (2)
> 
> |<3>| HSK[0x7f618c004ea0]: certificate[0] PK algorithm: RSA (1) - ctype:
> OPENPGP (2)
> 
> |<3>| HSK[0x7f618c004ea0]: Requested PK algorithm: RSA (1) -- ctype: OPENPGP
> 
> (2)
> 
> |<3>| HSK[0x7f618c004ea0]: certificate[0] PK algorithm: RSA (1) - ctype:
> OPENPGP (2)
> 
> |<3>| HSK[0x7f618c004ea0]: Removing ciphersuite:
> |ECDHE_ECDSA_AES_128_CBC_SHA1
> |<3>| HSK[0x7f618c004ea0]: Removing ciphersuite:
> ECDHE_ECDSA_AES_128_CBC_SHA256
> 
> |<3>| HSK[0x7f618c004ea0]: Removing ciphersuite:
> ECDHE_ECDSA_AES_128_GCM_SHA256
> 
> |<3>| HSK[0x7f618c004ea0]: Removing ciphersuite:
> |ECDHE_ECDSA_AES_256_CBC_SHA1
> |<3>| HSK[0x7f618c004ea0]: Removing ciphersuite:
> ECDHE_ECDSA_AES_256_CBC_SHA384
> 
> |<3>| HSK[0x7f618c004ea0]: Removing ciphersuite:
> ECDHE_ECDSA_AES_256_GCM_SHA384
> 
> |<3>| HSK[0x7f618c004ea0]: Removing ciphersuite:
> |ECDHE_ECDSA_3DES_EDE_CBC_SHA1 <3>| HSK[0x7f618c004ea0]: Keeping
> |ciphersuite: ECDHE_RSA_AES_128_CBC_SHA1
> (C0.13)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: ECDHE_RSA_AES_128_CBC_SHA256
> 
> (C0.27)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: ECDHE_RSA_AES_128_GCM_SHA256
> 
> (C0.2F)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: ECDHE_RSA_AES_256_CBC_SHA1
> 
> (C0.14)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: ECDHE_RSA_AES_256_GCM_SHA384
> 
> (C0.30)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: ECDHE_RSA_3DES_EDE_CBC_SHA1
> 
> (C0.12)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: RSA_AES_128_CBC_SHA1 (00.2F)
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: RSA_AES_128_CBC_SHA256
> |(00.3C) <3>| HSK[0x7f618c004ea0]: Keeping ciphersuite:
> |RSA_CAMELLIA_128_CBC_SHA1
> (00.41)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: RSA_AES_128_GCM_SHA256
> |(00.9C) <3>| HSK[0x7f618c004ea0]: Keeping ciphersuite:
> |RSA_AES_256_CBC_SHA1 (00.35) <3>| HSK[0x7f618c004ea0]: Keeping
> |ciphersuite: RSA_AES_256_CBC_SHA256 (00.3D) <3>| HSK[0x7f618c004ea0]:
> |Keeping ciphersuite: RSA_CAMELLIA_256_CBC_SHA1
> (00.84)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: RSA_3DES_EDE_CBC_SHA1
> |(00.0A) <3>| HSK[0x7f618c004ea0]: Keeping ciphersuite:
> |DHE_RSA_AES_128_CBC_SHA1
> (00.33)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: DHE_RSA_AES_128_CBC_SHA256
> 
> (00.67)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite:
> |DHE_RSA_CAMELLIA_128_CBC_SHA1
> (00.45)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: DHE_RSA_AES_128_GCM_SHA256
> 
> (00.9E)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: DHE_RSA_AES_256_CBC_SHA1
> 
> (00.39)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: DHE_RSA_AES_256_CBC_SHA256
> 
> (00.6B)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite:
> |DHE_RSA_CAMELLIA_256_CBC_SHA1
> (00.88)
> 
> |<3>| HSK[0x7f618c004ea0]: Keeping ciphersuite: DHE_RSA_3DES_EDE_CBC_SHA1
> 
> (00.16)
> 
> |<3>| HSK[0x7f618c004ea0]: Removing ciphersuite: DHE_DSS_AES_128_CBC_SHA1
> |<3>| HSK[0x7f618c004ea0]: Removing ciphersuite: DHE_DSS_AES_128_CBC_SHA256
> |<3>| HSK[0x7f618c004ea0]: Removing ciphersuite:
> |DHE_DSS_CAMELLIA_128_CBC_SHA1 <3>| HSK[0x7f618c004ea0]: Removing
> |ciphersuite: DHE_DSS_AES_128_GCM_SHA256 <3>| HSK[0x7f618c004ea0]: Removing
> |ciphersuite: DHE_DSS_AES_256_CBC_SHA1 <3>| HSK[0x7f618c004ea0]: Removing
> |ciphersuite: DHE_DSS_AES_256_CBC_SHA256 <3>| HSK[0x7f618c004ea0]: Removing
> |ciphersuite: DHE_DSS_CAMELLIA_256_CBC_SHA1 <3>| HSK[0x7f618c004ea0]:
> |Removing ciphersuite: DHE_DSS_3DES_EDE_CBC_SHA1 <3>| HSK[0x7f618c004ea0]:
> |Requested cipher suites[size: 74]:
> |<3>|   0xc0, 0x09 ECDHE_ECDSA_AES_128_CBC_SHA1
> |<3>|   0xc0, 0x23 ECDHE_ECDSA_AES_128_CBC_SHA256
> |<3>|   0xc0, 0x2b ECDHE_ECDSA_AES_128_GCM_SHA256
> |<3>|   0xc0, 0x0a ECDHE_ECDSA_AES_256_CBC_SHA1
> |<3>|   0xc0, 0x24 ECDHE_ECDSA_AES_256_CBC_SHA384
> |<3>|   0xc0, 0x2c ECDHE_ECDSA_AES_256_GCM_SHA384
> |<3>|   0xc0, 0x08 ECDHE_ECDSA_3DES_EDE_CBC_SHA1
> |<3>|   0xc0, 0x13 ECDHE_RSA_AES_128_CBC_SHA1
> |<3>| HSK[0x7f618c004ea0]: Selected cipher suite: ECDHE_RSA_AES_128_CBC_SHA1
> |<3>| HSK[0x7f618c004ea0]: Selected Compression Method: NULL
> |<3>| HSK[0x7f618c004ea0]: Safe renegotiation succeeded
> |<2>| ASSERT: /libgnutls/lib/ext/status_request.c:197
> |<3>| EXT[0x7f618c004ea0]: Sending extension CERT TYPE (1 bytes)
> |<3>| EXT[0x7f618c004ea0]: Sending extension SAFE RENEGOTIATION (1 bytes)
> |<2>| HB: sending parameter 1
> |<3>| EXT[0x7f618c004ea0]: Sending extension HEARTBEAT (1 bytes)
> |<3>| EXT[0x7f618c004ea0]: Sending extension SUPPORTED ECC POINT FORMATS (2
> 
> bytes)
> 
> |<3>| HSK[0x7f618c004ea0]: SessionID:
> a9a8d07103670e3b14aad8e1e316f6fb41f1a6298b2ae96b7126ada49201db51
> 
> |<3>| HSK[0x7f618c004ea0]: SERVER HELLO was queued [105 bytes]
> |<7>| HWRITE: enqueued [SERVER HELLO] 105. Total 105 bytes.
> |<3>| Sending PGP key ID d223dc8428ac7593 (subkey)
> |<3>| HSK[0x7f618c004ea0]: CERTIFICATE was queued [1134 bytes]
> |<7>| HWRITE: enqueued [CERTIFICATE] 1134. Total 1239 bytes.
> |<3>| HSK[0x7f618c004ea0]: signing handshake data: using RSA-SHA1
> |<9>| Looking keyid: d223dc84.28ac7593
> |<9>| Found keyid: d223dc84.28ac7593
> |<9>| Signing using PGP key ID d223dc8428ac7593
> |<9>| Looking keyid: d223dc84.28ac7593
> |<9>| Found keyid: d223dc84.28ac7593
> |<3>| HSK[0x7f618c004ea0]: SERVER KEY EXCHANGE was queued [195 bytes]
> |<7>| HWRITE: enqueued [SERVER KEY EXCHANGE] 195. Total 1434 bytes.
> |<3>| HSK[0x7f618c004ea0]: CERTIFICATE REQUEST was queued [18 bytes]
> |<7>| HWRITE: enqueued [CERTIFICATE REQUEST] 18. Total 1452 bytes.
> |<3>| HSK[0x7f618c004ea0]: SERVER HELLO DONE was queued [12 bytes]
> |<7>| HWRITE: enqueued [SERVER HELLO DONE] 12. Total 1464 bytes.
> |<7>| HWRITE FLUSH: 1464 bytes in buffer.
> |<6>| DTLS[0x7f618c004ea0]: Start of flight transmission.
> |<6>| DTLS[0x7f618c004ea0]: Sending Packet[1] fragment SERVER HELLO(2) with
> 
> length: 93, offset: 0, fragment length: 93
> 
> |<4>| REC[0x7f618c004ea0]: Preparing Packet Handshake(22) with length: 105
> |and
> target length: 105
> 
> |<9>| ENC[0x7f618c004ea0]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
> |<7>| WRITE: enqueued 118 bytes for 0x7f618c004cc0. Total 118 bytes.
> 
> |<4>| REC[0x7f618c004ea0]: Sent Packet[2] Handshake(22) in epoch 0 and 
length:
> 118
> 
> |<6>| DTLS[0x7f618c004ea0]: Sending Packet[2] fragment CERTIFICATE(11) with
> 
> length: 1122, offset: 0, fragment length: 1122
> 
> |<4>| REC[0x7f618c004ea0]: Preparing Packet Handshake(22) with length: 1134
> 
> and target length: 1134
> 
> |<9>| ENC[0x7f618c004ea0]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
> |<7>| WRITE: enqueued 1147 bytes for 0x7f618c004cc0. Total 1265 bytes.
> 
> |<4>| REC[0x7f618c004ea0]: Sent Packet[3] Handshake(22) in epoch 0 and 
length:
> 1147
> 
> |<6>| DTLS[0x7f618c004ea0]: Sending Packet[3] fragment SERVER KEY
> |EXCHANGE(12)
> with length: 183, offset: 0, fragment length: 183
> 
> |<4>| REC[0x7f618c004ea0]: Preparing Packet Handshake(22) with length: 195
> |and
> target length: 195
> 
> |<9>| ENC[0x7f618c004ea0]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
> |<7>| WRITE: enqueued 208 bytes for 0x7f618c004cc0. Total 1473 bytes.
> 
> |<4>| REC[0x7f618c004ea0]: Sent Packet[4] Handshake(22) in epoch 0 and 
length:
> 208
> 
> |<6>| DTLS[0x7f618c004ea0]: Sending Packet[4] fragment CERTIFICATE
> |REQUEST(13)
> with length: 6, offset: 0, fragment length: 6
> 
> |<4>| REC[0x7f618c004ea0]: Preparing Packet Handshake(22) with length: 18
> |and
> target length: 18
> 
> |<9>| ENC[0x7f618c004ea0]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
> |<7>| WRITE: enqueued 31 bytes for 0x7f618c004cc0. Total 1504 bytes.
> 
> |<4>| REC[0x7f618c004ea0]: Sent Packet[5] Handshake(22) in epoch 0 and 
length:
> 31
> 
> |<6>| DTLS[0x7f618c004ea0]: Sending Packet[5] fragment SERVER HELLO DONE(14)
> 
> with length: 0, offset: 0, fragment length: 0
> 
> |<4>| REC[0x7f618c004ea0]: Preparing Packet Handshake(22) with length: 12
> |and
> target length: 12
> 
> |<9>| ENC[0x7f618c004ea0]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
> |<7>| WRITE: enqueued 25 bytes for 0x7f618c004cc0. Total 1529 bytes.
> 
> |<4>| REC[0x7f618c004ea0]: Sent Packet[6] Handshake(22) in epoch 0 and 
length:
> 25
> 
> |<7>| WRITE FLUSH: 1529 bytes in buffer.
> 
> _______________________________ send(): 118
> _______________________________ send(): 1147
> _______________________________ send(): 208
> _______________________________ send(): 31
> _______________________________ send(): 25
> 
> |<7>| WRITE: wrote 1529 bytes, 0 bytes left.
> 
> ________________________________-timeout: 0 dtlstm: 0 :: bytes_available: 0
> 
> |<7>| READ_TIMEOUT: -1 returned from 0x7f618c004cc0, errno=11 (timeout: 0)
> |<2>| ASSERT: /libgnutls/lib/gnutls_dtls.c:380
> |<6>| DTLS[0x7f618c004ea0]: End of flight transmission.
> 
> _______________________________ handshake(): -28
> _______________________________ receive(): 1138
> 
> |<7>| HWRITE FLUSH: 0 bytes in buffer.
> |<6>| DTLS[0x7f618c004ea0]: Start of flight transmission.
> |<7>| WRITE FLUSH: 0 bytes in buffer.
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:610
> 
> ________________________________-timeout: 0 dtlstm: 1 :: bytes_available:
> 1138 ________________________________ pull(): 1138
> 
> |<7>| READ: Got 1138 bytes from 0x7f618c004cc0
> |<7>| READ: read 1138 bytes from 0x7f618c004cc0
> |<7>| RB: Have 0 bytes into buffer. Adding 1138 bytes.
> |<7>| RB: Requested 13 bytes
> |<4>| REC[0x7f618c004ea0]: SSL 254.255 Handshake packet received. Epoch 0,
> 
> length: 1125
> 
> |<4>| REC[0x7f618c004ea0]: Expected Packet Handshake(22)
> |<4>| REC[0x7f618c004ea0]: Received Packet Handshake(22) with length: 1125
> 
> |<4>| REC[0x7f618c004ea0]: Decrypted Packet[0.2] Handshake(22) with length:
> 1125
> 
> |<6>| BUF[REC]: Inserted 1125 bytes of Data(22)
> |<3>| HSK[0x7f618c004ea0]: CERTIFICATE (11) was received. Length 1113[1113],
> 
> frag offset 0, frag length: 1113, sequence: 2
> 
> |<6>| DTLS[0x7f618c004ea0]: End of flight transmission.
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1192
> |<2>| ASSERT: /libgnutls/lib/opencdk/stream.c:1035
> |<9>| Looking keyid: b4fad0a3.3fa33930
> |<9>| Found keyid: b4fad0a3.3fa33930
> |<2>| ASSERT: /libgnutls/lib/openpgp/pgp.c:172
> |<9>| Looking keyid: b4fad0a3.3fa33930
> |<9>| Found keyid: b4fad0a3.3fa33930
> 
> ________________________________ verify()
> 
> |<2>| ASSERT: /libgnutls/lib/opencdk/stream.c:1035
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> 
> ________________________________ pull(): 0
> 
> |<7>| READ: -1 returned from 0x7f618c004cc0, errno=11 gerrno=11
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:508
> 
> ________________________________ handshake(): gnutls:-28
> ________________________________ receive(): 155
> 
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> 
> ________________________________ pull(): 155
> 
> |<7>| READ: Got 155 bytes from 0x7f618c004cc0
> |<7>| READ: read 155 bytes from 0x7f618c004cc0
> |<7>| RB: Have 0 bytes into buffer. Adding 155 bytes.
> |<7>| RB: Requested 13 bytes
> |<4>| REC[0x7f618c004ea0]: SSL 254.255 Handshake packet received. Epoch 0,
> 
> length: 142
> 
> |<4>| REC[0x7f618c004ea0]: Expected Packet Handshake(22)
> |<4>| REC[0x7f618c004ea0]: Received Packet Handshake(22) with length: 142
> 
> |<4>| REC[0x7f618c004ea0]: Decrypted Packet[0.4] Handshake(22) with length:
> 142
> 
> |<6>| BUF[REC]: Inserted 142 bytes of Data(22)
> |<3>| HSK[0x7f618c004ea0]: CERTIFICATE VERIFY (15) was received. Length
> 
> 130[130], frag offset 0, frag length: 130, sequence: 4
> 
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> 
> __________________________________________ handshake(): gnutls:-28
> __________________________________________ session::receive(): 14
> 
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> 
> __________________________________________ pull(): 14
> 
> |<7>| READ: Got 14 bytes from 0x7f618c004cc0
> |<7>| READ: read 14 bytes from 0x7f618c004cc0
> |<7>| RB: Have 0 bytes into buffer. Adding 14 bytes.
> |<7>| RB: Requested 13 bytes
> |<4>| REC[0x7f618c004ea0]: SSL 254.255 ChangeCipherSpec packet received.
> |Epoch
> 0, length: 1
> 
> |<4>| REC[0x7f618c004ea0]: Expected Packet Handshake(22)
> |<4>| REC[0x7f618c004ea0]: Received Packet ChangeCipherSpec(20) with length:
> |1 <4>| REC[0x7f618c004ea0]: Decrypted Packet[0.5] ChangeCipherSpec(20)
> |with
> length: 1
> 
> |<6>| BUF[REC]: Inserted 1 bytes of Data(20)
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1119
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> 
> __________________________________________ handshake(): gnutls:-28
> __________________________________________ receive(): 77
> 
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1119
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> 
> __________________________________________ pull(): 77
> 
> |<7>| READ: Got 77 bytes from 0x7f618c004cc0
> |<7>| READ: read 77 bytes from 0x7f618c004cc0
> |<7>| RB: Have 0 bytes into buffer. Adding 77 bytes.
> |<7>| RB: Requested 13 bytes
> |<4>| REC[0x7f618c004ea0]: SSL 254.255 Handshake packet received. Epoch 1,
> 
> length: 64
> 
> |<4>| REC[0x7f618c004ea0]: Expected Packet Handshake(22)
> |<4>| REC[0x7f618c004ea0]: Received Packet Handshake(22) with length: 64
> |<1>| Discarded duplicate message[0]: Handshake
> |<2>| ASSERT: /libgnutls/lib/gnutls_record.c:1263
> 
> __________________________________________ handshake(): -28
> _________________________________ dtls timeout:0
> _________________________________ dtls direction: 0
> 
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1119
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> 
> __________________________________________ pull(): 0
> 
> |<7>| READ: -1 returned from 0x7f618c004cc0, errno=0 gerrno=11
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:508
> 
> __________________________________________ handshake(): gnutls:-28
> __________________________________________ receive(): 75
> 
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1119
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> 
> __________________________________________ pull(): 75
> 
> |<7>| READ: Got 75 bytes from 0x7f618c004cc0
> |<7>| READ: read 75 bytes from 0x7f618c004cc0
> |<7>| RB: Have 0 bytes into buffer. Adding 75 bytes.
> |<7>| RB: Requested 13 bytes
> |<4>| REC[0x7f618c004ea0]: SSL 254.255 Handshake packet received. Epoch 0,
> 
> length: 62
> 
> |<4>| REC[0x7f618c004ea0]: Expected Packet Handshake(22)
> |<4>| REC[0x7f618c004ea0]: Received Packet Handshake(22) with length: 62
> |<4>| REC[0x7f618c004ea0]: Decrypted Packet[0.3] Handshake(22) with length:
> |62 <6>| BUF[REC]: Inserted 62 bytes of Data(22)
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1119
> |<3>| HSK[0x7f618c004ea0]: CLIENT KEY EXCHANGE (16) was received. Length
> 
> 50[50], frag offset 0, frag length: 50, sequence: 3
> 
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1192
> |<2>| ASSERT: /libgnutls/lib/ext/signature.c:308
> |<2>| ASSERT: /libgnutls/lib/opencdk/stream.c:1035
> |<9>| Looking keyid: b4fad0a3.3fa33930
> |<9>| Found keyid: b4fad0a3.3fa33930
> |<2>| ASSERT: /libgnutls/lib/openpgp/pgp.c:172
> |<9>| Looking keyid: b4fad0a3.3fa33930
> |<9>| Found keyid: b4fad0a3.3fa33930
> |<3>| HSK[0x7f618c004ea0]: verify cert vrfy: using (null)
> 
> |<9>| INT: PREMASTER SECRET[24]:
> 5bf7c4f4932f4e85ea2d75b4e8acec9bb5c7a95634887c7e
> 
> |<9>| INT: CLIENT RANDOM[32]:
> 51646c5e454b65370f2f2b265bfd9f7c25c54e683e87283273e14c25124bab3c
> 
> |<9>| INT: SERVER RANDOM[32]:
> 51646c5ee466356814339cf4c241559f76826764c4b9eecf542fc3ce5ae780b9
> 
> |<9>| INT: MASTER SECRET:
> 92fae9b24a6a51e8eee862698118b09edbe8e9cd73e46aae411aa4915a10d8d56a29694e5f78
> 98c2c8d593017cc5b933
> |<4>| REC[0x7f618c004ea0]: Initializing epoch #1
> 
> |<9>| INT: KEY BLOCK[104]:
> 7bce9e55f7b05fa76535a96ce713f3a4c22dabce8d72bc933a0d2775930865fd
> 
> |<9>| INT: CLIENT WRITE KEY [16]: 977ad535ba37537ce8482d5bd53424be
> |<9>| INT: SERVER WRITE KEY [16]: 038ebacb3af16c5cfa0f7f1770e5e6d1
> |<4>| REC[0x7f618c004ea0]: Epoch #1 ready
> |<3>| HSK[0x7f618c004ea0]: Cipher Suite: ECDHE_RSA_AES_128_CBC_SHA1
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:1019
> 
> __________________________________________ pull(): 0
> 
> |<7>| READ: -1 returned from 0x7f618c004cc0, errno=11 gerrno=11
> |<2>| ASSERT: /libgnutls/lib/gnutls_buffers.c:508
> |<2>| ASSERT: /libgnutls/lib/gnutls_handshake.c:739
> |<2>| ASSERT: /libgnutls/lib/gnutls_handshake.c:2937
> 
> __________________________________________ handshake(): gnutls:-28