[gnutls-help] failing DTLS handshake

[Balázs Kéri]

Hi!

I have a case when DTLS handshake is performed and GnuTLS server side seems
to not send out the last messages.

the observed message sequence:

client->server:
ClientHello (total 164 bytes)

server->client:
ServerHello,Certificate,CertificateRequest,ServerHelloDone (total 1159
bytes)

client->server:
Certificate(Fragment)(243),Certificate(Fragment)(243),Cer
tificate(Fragment)(243),Certificate(Fragment)(243),Certifica
te(Fragment)(13),ClientKeyExchange(142),CertificateVerify(62),
CertificateVerify(92) (total 1427 bytes)

client->server:
ChangeCipherSpec(1),EncryptedHandshakeMessage(64) (total 133 bytes)

(The last EncryptedHandshakeMessage is probably a Finished.)

At this point the server should send the ChangeCipherSpec or any other
message, but it does send nothing. According to the log the correct data is
passed to GnuTLS by the 'pull' function, but the 'gnutls_handshake'
function returns EAGAIN repeatedly without continuing the handshake
sequence (the 'push' is not called). The GnuTLS log messages are in the
attached log file. Following seems to be problematic (the last one is
printed after the last EncryptedHandshakeMessage is received, the other
after the last fragment of Certificate was received with fragment length of
1 byte):

533 [2017-Aug-24 10:13:38.768873]  GnuTLS -- [level:1]: Invalid handshake
packet headers. Discarding.
569 [2017-Aug-24 10:13:38.770813]  GnuTLS -- [level:5]:
REC[0x7f9ce0013ea0]: Discarded duplicate message[1.0]: Handshake

The problem happens with GnuTLS 3.3.19, 3.3.28 and 3.5.15 too (logs are
from version 3.3.15).
What could be wrong here?

Balázs Kéri
-------------- next part --------------
An HTML attachment was scrubbed...
URL: </pipermail/attachments/20170828/e0211c88/attachment-0001.html>
-------------- next part --------------
399 [2017-Aug-24 10:13:38.761385]  GnuTLS -- [level:3]: ASSERT: constate.c[_gnutls_epoch_get]:600
400 [2017-Aug-24 10:13:38.761413]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Allocating epoch #1
401 [2017-Aug-24 10:13:38.761439]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1163
402 [2017-Aug-24 10:13:38.761468]  pull 122 bytes
403 [2017-Aug-24 10:13:38.761498]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 Handshake packet received. Epoch 0, length: 109
404 [2017-Aug-24 10:13:38.761521]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
405 [2017-Aug-24 10:13:38.761543]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet Handshake(22) with length: 109
406 [2017-Aug-24 10:13:38.761627]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Decrypted Packet[0.3] Handshake(22) with length: 109
407 [2017-Aug-24 10:13:38.761665]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CLIENT HELLO (1) was received. Length 97[97], frag offset 0, frag length: 97, sequence: 0
408 [2017-Aug-24 10:13:38.761694]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Client's version: 254.253
409 [2017-Aug-24 10:13:38.761734]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Selected version DTLS1.0
410 [2017-Aug-24 10:13:38.761768]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: Found extension 'Signature Algorithms/13'
411 [2017-Aug-24 10:13:38.761790]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: Found extension 'SRTP/14'
412 [2017-Aug-24 10:13:38.761812]  GnuTLS -- [level:3]: ASSERT: db.c[_gnutls_server_restore_session]:272
413 [2017-Aug-24 10:13:38.761835]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: Found extension 'Signature Algorithms/13'
414 [2017-Aug-24 10:13:38.761857]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: Parsing extension 'SRTP/14' (7 bytes)
415 [2017-Aug-24 10:13:38.761881]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: Parsing extension 'Signature Algorithms/13' (32 bytes)
416 [2017-Aug-24 10:13:38.761909]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (6.1) RSA-SHA512
417 [2017-Aug-24 10:13:38.761932]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (6.2) DSA-SHA512
418 [2017-Aug-24 10:13:38.761953]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (6.3) ECDSA-SHA512
419 [2017-Aug-24 10:13:38.761975]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (5.1) RSA-SHA384
420 [2017-Aug-24 10:13:38.761997]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (5.2) DSA-SHA384
421 [2017-Aug-24 10:13:38.762018]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (5.3) ECDSA-SHA384
422 [2017-Aug-24 10:13:38.762040]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (4.1) RSA-SHA256
423 [2017-Aug-24 10:13:38.762061]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (4.2) DSA-SHA256
424 [2017-Aug-24 10:13:38.762082]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (4.3) ECDSA-SHA256
425 [2017-Aug-24 10:13:38.762103]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (3.1) RSA-SHA224
426 [2017-Aug-24 10:13:38.762138]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (3.2) DSA-SHA224
427 [2017-Aug-24 10:13:38.762161]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (3.3) ECDSA-SHA224
428 [2017-Aug-24 10:13:38.762182]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (2.1) RSA-SHA1
429 [2017-Aug-24 10:13:38.762203]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (2.2) DSA-SHA1
430 [2017-Aug-24 10:13:38.762224]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: rcvd signature algo (2.3) ECDSA-SHA1
431 [2017-Aug-24 10:13:38.762246]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: Found extension 'SRTP/14'
432 [2017-Aug-24 10:13:38.762268]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Received safe renegotiation CS
433 [2017-Aug-24 10:13:38.762417]  GnuTLS -- [level:3]: ASSERT: server_name.c[gnutls_server_name_get]:310
434 [2017-Aug-24 10:13:38.762443]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Requested server name: ''
435 [2017-Aug-24 10:13:38.762475]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Requested PK algorithm: RSA (1) -- ctype: X.509 (1)
436 [2017-Aug-24 10:13:38.762499]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: certificate[0] PK algorithm: RSA (1) - ctype: X.509 (1)
437 [2017-Aug-24 10:13:38.762533]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Keeping ciphersuite: GNUTLS_RSA_AES_256_CBC_SHA1 (00.35)
438 [2017-Aug-24 10:13:38.762556]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_256_CBC_SHA1 (00.84)
439 [2017-Aug-24 10:13:38.762577]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Keeping ciphersuite: GNUTLS_RSA_AES_128_CBC_SHA1 (00.2F)
440 [2017-Aug-24 10:13:38.762599]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_128_CBC_SHA1 (00.41)
441 [2017-Aug-24 10:13:38.762621]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Keeping ciphersuite: GNUTLS_RSA_3DES_EDE_CBC_SHA1 (00.0A)
442 [2017-Aug-24 10:13:38.762644]  GnuTLS -- [level:3]: ASSERT: ciphersuites.c[check_server_params]:1300
443 [2017-Aug-24 10:13:38.762665]  GnuTLS -- [level:3]: ASSERT: ciphersuites.c[check_server_params]:1300
444 [2017-Aug-24 10:13:38.762688]  GnuTLS -- [level:3]: ASSERT: ciphersuites.c[check_server_params]:1300
445 [2017-Aug-24 10:13:38.762709]  GnuTLS -- [level:3]: ASSERT: ciphersuites.c[check_server_params]:1300
446 [2017-Aug-24 10:13:38.762730]  GnuTLS -- [level:3]: ASSERT: ciphersuites.c[check_server_params]:1300
447 [2017-Aug-24 10:13:38.762751]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Requested cipher suites[size: 8]: 
448 [2017-Aug-24 10:13:38.762772]  GnuTLS -- [level:4]: 	0x00, 0x2f RSA_AES_128_CBC_SHA1
449 [2017-Aug-24 10:13:38.762794]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Selected cipher suite: RSA_AES_128_CBC_SHA1
450 [2017-Aug-24 10:13:38.762820]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Selected Compression Method: NULL
451 [2017-Aug-24 10:13:38.762842]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: Found extension 'Signature Algorithms/13'
452 [2017-Aug-24 10:13:38.762863]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: Found extension 'SRTP/14'
453 [2017-Aug-24 10:13:38.762896]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: Safe renegotiation succeeded
454 [2017-Aug-24 10:13:38.762927]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: Sending extension Safe Renegotiation (1 bytes)
455 [2017-Aug-24 10:13:38.762951]  GnuTLS -- [level:4]: EXT[0x7f9ce0013ea0]: Sending extension SRTP (5 bytes)
456 [2017-Aug-24 10:13:38.762987]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: SessionID: 7c34816fe1ca5d1fde2ebed4f63a19884faf0e063788e58c7fec7c61b100e146
457 [2017-Aug-24 10:13:38.763010]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: SERVER HELLO was queued [98 bytes]
458 [2017-Aug-24 10:13:38.763038]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CERTIFICATE was queued [937 bytes]
459 [2017-Aug-24 10:13:38.763066]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CERTIFICATE REQUEST was queued [18 bytes]
460 [2017-Aug-24 10:13:38.763088]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: SERVER HELLO DONE was queued [12 bytes]
461 [2017-Aug-24 10:13:38.763112]  GnuTLS -- [level:6]: DTLS[0x7f9ce0013ea0]: Start of flight transmission.
462 [2017-Aug-24 10:13:38.763139]  GnuTLS -- [level:6]: DTLS[0x7f9ce0013ea0]: Sending Packet[0] fragment SERVER HELLO(2) with length: 86, offset: 0, fragment length: 86, mtu: 1427
463 [2017-Aug-24 10:13:38.763163]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Preparing Packet Handshake(22) with length: 98 and min pad: 0
464 [2017-Aug-24 10:13:38.763186]  GnuTLS -- [level:9]: ENC[0x7f9ce0013ea0]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
465 [2017-Aug-24 10:13:38.763210]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Sent Packet[1] Handshake(22) in epoch 0 and length: 111
466 [2017-Aug-24 10:13:38.763234]  GnuTLS -- [level:6]: DTLS[0x7f9ce0013ea0]: Sending Packet[1] fragment CERTIFICATE(11) with length: 925, offset: 0, fragment length: 925, mtu: 1427
467 [2017-Aug-24 10:13:38.763258]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Preparing Packet Handshake(22) with length: 937 and min pad: 0
468 [2017-Aug-24 10:13:38.763280]  GnuTLS -- [level:9]: ENC[0x7f9ce0013ea0]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
469 [2017-Aug-24 10:13:38.763303]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Sent Packet[2] Handshake(22) in epoch 0 and length: 950
470 [2017-Aug-24 10:13:38.763326]  GnuTLS -- [level:6]: DTLS[0x7f9ce0013ea0]: Sending Packet[2] fragment CERTIFICATE REQUEST(13) with length: 6, offset: 0, fragment length: 6, mtu: 1427
471 [2017-Aug-24 10:13:38.763349]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Preparing Packet Handshake(22) with length: 18 and min pad: 0
472 [2017-Aug-24 10:13:38.763371]  GnuTLS -- [level:9]: ENC[0x7f9ce0013ea0]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
473 [2017-Aug-24 10:13:38.763393]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Sent Packet[3] Handshake(22) in epoch 0 and length: 31
474 [2017-Aug-24 10:13:38.763416]  GnuTLS -- [level:6]: DTLS[0x7f9ce0013ea0]: Sending Packet[3] fragment SERVER HELLO DONE(14) with length: 0, offset: 0, fragment length: 0, mtu: 1427
475 [2017-Aug-24 10:13:38.763439]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Preparing Packet Handshake(22) with length: 12 and min pad: 0
476 [2017-Aug-24 10:13:38.763460]  GnuTLS -- [level:9]: ENC[0x7f9ce0013ea0]: cipher: NULL, MAC: MAC-NULL, Epoch: 0
477 [2017-Aug-24 10:13:38.763482]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Sent Packet[4] Handshake(22) in epoch 0 and length: 25
478 [2017-Aug-24 10:13:38.763552]  push_vec 1117
480 [2017-Aug-24 10:13:38.763616]  GnuTLS -- [level:3]: ASSERT: dtls.c[_dtls_transmit]:420
481 [2017-Aug-24 10:13:38.763636]  handshake - after
485 [2017-Aug-24 10:13:38.764741]  handshake - before
486 [2017-Aug-24 10:13:38.764802]  GnuTLS -- [level:3]: ASSERT: buffers.c[_gnutls_io_write_flush]:694
488 [2017-Aug-24 10:13:38.764847]  GnuTLS -- [level:3]: ASSERT: dtls.c[_dtls_transmit]:263
489 [2017-Aug-24 10:13:38.764867]  GnuTLS -- [level:3]: ASSERT: dtls.c[_dtls_transmit]:420
490 [2017-Aug-24 10:13:38.764885]  handshake - after
497 [2017-Aug-24 10:13:38.767992]  handshake - before
498 [2017-Aug-24 10:13:38.768053]  GnuTLS -- [level:3]: ASSERT: buffers.c[_gnutls_io_write_flush]:694
500 [2017-Aug-24 10:13:38.768101]  pull 1385 bytes
501 [2017-Aug-24 10:13:38.768127]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 Handshake packet received. Epoch 0, length: 243
502 [2017-Aug-24 10:13:38.768150]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
503 [2017-Aug-24 10:13:38.768172]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet Handshake(22) with length: 243
504 [2017-Aug-24 10:13:38.768198]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Decrypted Packet[0.4] Handshake(22) with length: 243
505 [2017-Aug-24 10:13:38.768224]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CERTIFICATE (11) was received. Length 925[231], frag offset 0, frag length: 231, sequence: 1
506 [2017-Aug-24 10:13:38.768250]  GnuTLS -- [level:6]: DTLS[0x7f9ce0013ea0]: End of flight transmission.
507 [2017-Aug-24 10:13:38.768275]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1139
508 [2017-Aug-24 10:13:38.768298]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 Handshake packet received. Epoch 0, length: 243
509 [2017-Aug-24 10:13:38.768335]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
510 [2017-Aug-24 10:13:38.768358]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet Handshake(22) with length: 243
511 [2017-Aug-24 10:13:38.768384]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Decrypted Packet[0.5] Handshake(22) with length: 243
512 [2017-Aug-24 10:13:38.768408]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CERTIFICATE (11) was received. Length 925[231], frag offset 231, frag length: 231, sequence: 1
513 [2017-Aug-24 10:13:38.768432]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1139
514 [2017-Aug-24 10:13:38.768455]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 Handshake packet received. Epoch 0, length: 243
515 [2017-Aug-24 10:13:38.768476]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
516 [2017-Aug-24 10:13:38.768497]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet Handshake(22) with length: 243
517 [2017-Aug-24 10:13:38.768520]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Decrypted Packet[0.6] Handshake(22) with length: 243
518 [2017-Aug-24 10:13:38.768544]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CERTIFICATE (11) was received. Length 925[231], frag offset 462, frag length: 231, sequence: 1
519 [2017-Aug-24 10:13:38.768567]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1139
520 [2017-Aug-24 10:13:38.768589]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 Handshake packet received. Epoch 0, length: 243
521 [2017-Aug-24 10:13:38.768610]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
522 [2017-Aug-24 10:13:38.768631]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet Handshake(22) with length: 243
523 [2017-Aug-24 10:13:38.768654]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Decrypted Packet[0.7] Handshake(22) with length: 243
524 [2017-Aug-24 10:13:38.768677]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CERTIFICATE (11) was received. Length 925[231], frag offset 693, frag length: 231, sequence: 1
525 [2017-Aug-24 10:13:38.768700]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1139
526 [2017-Aug-24 10:13:38.768722]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 Handshake packet received. Epoch 0, length: 13
527 [2017-Aug-24 10:13:38.768744]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
528 [2017-Aug-24 10:13:38.768764]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet Handshake(22) with length: 13
529 [2017-Aug-24 10:13:38.768787]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Decrypted Packet[0.8] Handshake(22) with length: 13
530 [2017-Aug-24 10:13:38.768811]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CERTIFICATE (11) was received. Length 925[1], frag offset 924, frag length: 1, sequence: 1
531 [2017-Aug-24 10:13:38.768832]  GnuTLS -- [level:3]: ASSERT: buffers.c[parse_handshake_header]:961
532 [2017-Aug-24 10:13:38.768852]  GnuTLS -- [level:3]: ASSERT: buffers.c[_gnutls_parse_record_buffered_msgs]:1292
533 [2017-Aug-24 10:13:38.768873]  GnuTLS -- [level:1]: Invalid handshake packet headers. Discarding.
534 [2017-Aug-24 10:13:38.768893]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1139
535 [2017-Aug-24 10:13:38.768926]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 Handshake packet received. Epoch 0, length: 142
536 [2017-Aug-24 10:13:38.768949]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
537 [2017-Aug-24 10:13:38.768970]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet Handshake(22) with length: 142
538 [2017-Aug-24 10:13:38.768995]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Decrypted Packet[0.9] Handshake(22) with length: 142
539 [2017-Aug-24 10:13:38.769019]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CLIENT KEY EXCHANGE (16) was received. Length 130[130], frag offset 0, frag length: 130, sequence: 2
540 [2017-Aug-24 10:13:38.769055]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1139
541 [2017-Aug-24 10:13:38.769080]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 Handshake packet received. Epoch 0, length: 62
542 [2017-Aug-24 10:13:38.769101]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
543 [2017-Aug-24 10:13:38.769121]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet Handshake(22) with length: 62
544 [2017-Aug-24 10:13:38.769144]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Decrypted Packet[0.10] Handshake(22) with length: 62
545 [2017-Aug-24 10:13:38.769168]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CERTIFICATE VERIFY (15) was received. Length 130[50], frag offset 0, frag length: 50, sequence: 3
546 [2017-Aug-24 10:13:38.769192]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1139
547 [2017-Aug-24 10:13:38.769214]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 Handshake packet received. Epoch 0, length: 92
548 [2017-Aug-24 10:13:38.769235]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
549 [2017-Aug-24 10:13:38.769255]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet Handshake(22) with length: 92
550 [2017-Aug-24 10:13:38.769279]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Decrypted Packet[0.11] Handshake(22) with length: 92
551 [2017-Aug-24 10:13:38.769302]  GnuTLS -- [level:4]: HSK[0x7f9ce0013ea0]: CERTIFICATE VERIFY (15) was received. Length 130[80], frag offset 50, frag length: 80, sequence: 3
552 [2017-Aug-24 10:13:38.769326]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1163
553 [2017-Aug-24 10:13:38.769346]  handshake - after
556 [2017-Aug-24 10:13:38.770447]  handshake - before
557 [2017-Aug-24 10:13:38.770510]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1163
558 [2017-Aug-24 10:13:38.770539]  pull 91 bytes
559 [2017-Aug-24 10:13:38.770565]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 ChangeCipherSpec packet received. Epoch 0, length: 1
560 [2017-Aug-24 10:13:38.770588]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
561 [2017-Aug-24 10:13:38.770609]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet ChangeCipherSpec(20) with length: 1
562 [2017-Aug-24 10:13:38.770651]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Decrypted Packet[0.12] ChangeCipherSpec(20) with length: 1
563 [2017-Aug-24 10:13:38.770677]  GnuTLS -- [level:3]: ASSERT: buffers.c[_gnutls_parse_record_buffered_msgs]:1282
564 [2017-Aug-24 10:13:38.770701]  GnuTLS -- [level:3]: ASSERT: buffers.c[get_last_packet]:1139
565 [2017-Aug-24 10:13:38.770724]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: SSL 254.255 Handshake packet received. Epoch 1, length: 64
566 [2017-Aug-24 10:13:38.770746]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Expected Packet Handshake(22)
567 [2017-Aug-24 10:13:38.770767]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Received Packet Handshake(22) with length: 64
568 [2017-Aug-24 10:13:38.770791]  GnuTLS -- [level:3]: ASSERT: dtls-sw.c[_dtls_record_check]:73
569 [2017-Aug-24 10:13:38.770813]  GnuTLS -- [level:5]: REC[0x7f9ce0013ea0]: Discarded duplicate message[1.0]: Handshake
570 [2017-Aug-24 10:13:38.770834]  GnuTLS -- [level:3]: ASSERT: record.c[_gnutls_recv_in_buffers]:1345
571 [2017-Aug-24 10:13:38.770853]  handshake - after