Receiving forst message after succcessfull TLS negotiation failed

Fri May 11 15:26:58 CEST 2012

Hello,

i am using a XMPP library (iksemel) with GnuTLS support for communication with a
XMPP server (GoogleTalk or Openfire).

The TLS negotiation (handshake) is performed without errors, but the firs read
request fails with following error code:

GNUTLS_E_UNEXPECTED_PACKET_LENGTH /* GNUTLS_A_RECORD_OVERFLOW */

Obviously, this as some kind of error, which is not ambiguous and points to some
deeper problem,
the question is, it is possible to "enable" some debuging information for gather
the really problem ?

Hare is the source code used for TLS negotiation:

static int
tls_handshake (struct ikstls_data **datap, ikstransport *trans, void *sock)
{
    const int protocol_priority[] = { GNUTLS_TLS1, GNUTLS_SSL3, 0 };
    const int kx_priority[] = { GNUTLS_KX_RSA, 0 };
    const int cipher_priority[] = { GNUTLS_CIPHER_3DES_CBC,
GNUTLS_CIPHER_ARCFOUR, 0};
    const int comp_priority[] = { GNUTLS_COMP_ZLIB, GNUTLS_COMP_NULL, 0 };
    const int mac_priority[] = { GNUTLS_MAC_SHA, GNUTLS_MAC_MD5, 0 };
    struct ikstls_data *data;
    int ret;

    *datap = NULL;

    data = iks_malloc (sizeof(*data));
    if (!data) return IKS_NOMEM;
    memset (data, 0, sizeof(*data));
    data->trans = trans;
    data->sock = sock;
    data->timeout = -1;

    if (gnutls_global_init () != 0) {
        iks_free (data);
        return IKS_NOMEM;
    }

    if (gnutls_certificate_allocate_credentials (&data->cred) < 0) {
        iks_free (data);
        return IKS_NOMEM;
    }

    if (gnutls_init (&data->sess, GNUTLS_CLIENT) != 0) {
        gnutls_certificate_free_credentials (data->cred);
        iks_free (data);
        return IKS_NOMEM;
    }

    gnutls_protocol_set_priority (data->sess, protocol_priority);
    gnutls_cipher_set_priority(data->sess, cipher_priority);
    gnutls_compression_set_priority(data->sess, comp_priority);
    gnutls_kx_set_priority(data->sess, kx_priority);
    gnutls_mac_set_priority(data->sess, mac_priority);
    gnutls_credentials_set (data->sess, GNUTLS_CRD_CERTIFICATE, data->cred);

    gnutls_transport_set_push_function (data->sess, (gnutls_push_func)
tls_push);
    gnutls_transport_set_pull_function (data->sess, (gnutls_pull_func)
tls_pull);
    gnutls_transport_set_ptr (data->sess, data);

    ret = gnutls_handshake (data->sess);
    if (ret != 0) {
        gnutls_deinit (data->sess);
        gnutls_certificate_free_credentials (data->cred);
        iks_free (data);
        return IKS_NET_TLSFAIL;
    }

    *datap = data;
    return IKS_OK;
}

Additionally is the session data flow:

SEND[<?xml version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client'
to='10.90.6.140' version='1.0'>]
RECV[<?xml version='1.0' encoding='UTF-8'?><stream:stream
xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client"
from="10.90.6.140" id="2cb01145" xml:lang="en"
version="1.0"><stream:features><starttls
xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required/></starttls><mechanisms
xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>DIGEST-MD5</mechanism><mechanism>PLAIN</mechanism><mechanism>ANONYMOUS</mechanism><mechanism>CRAM-MD5</mechanism></mechanisms></stream:features>]
SEND[<starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>]
RECV[<proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls"/>]

===> start TLS handshake

TLS GNUTLS: tls_handshake
TLS GNUTLS: tls_push: 55 bytes

16 03 01 00 32 01 00 00 2e 03 01 4f ad 00 10 ab
f2 66 d9 3f e2 d2 60 15 95 ef f5 c2 c7 c7 19 14
91 dd c2 f3 5f 38 93 4f 71 ef a5 00 00 06 00 0a
00 05 00 04 02 01 00

TLS GNUTLS: tls_pull

16 03 01 03 34

TLS GNUTLS: tls_pull

02 00 00 46 03 01 4f ad 00 10 c3 80 19 37 6a 4c
97 a3 19 a4 e6 a4 f9 f6 6d e9 37 c0 a5 53 e8 f7
f3 ee dd 9e 1f b1 20 4f ad 00 10 96 31 0b 0f e8
82 4a 50 c7 7f f1 42 36 45 98 81 ef 05 f5 8e 10
9b e1 7a ab be 58 f5 00 0a 00 0b 00 02 e2 00 02
df 00 02 dc 30 82 02 d8 30 82 01 c0 a0 03 02 01
02 02 08 67 bd 0d b9 b4 2c 66 23 30 0d 06 09 2a
86 48 86 f7 0d 01 01 05 05 00 30 16 31 14 30 12
06 03 55 04 03 0c 0b 31 30 2e 39 30 2e 36 2e 31
34 30 30 1e 17 0d 31 32 30 32 31 30 31 31 30 30
35 38 5a 17 0d 31 37 30 31 31 34 31 31 30 30 35
38 5a 30 16 31 14 30 12 06 03 55 04 03 0c 0b 31
30 2e 39 30 2e 36 2e 31 34 30 30 82 01 22 30 0d
06 09 2a 86 48 86 f7 0d 01 01 01 05 00 03 82 01
0f 00 30 82 01 0a 02 82 01 01 00 c7 da cc cf 72
8c 85 75 03 ee 1b 90 90 8f cd f2 db a0 14 fc bc
ed 74 28 a5 21 e0 52 7f f6 41 45 fa 17 95 f9 16
02 6b c4 e7 93 f2 3c be a8 34 ab b5 79 12 28 ba
39 43 18 44 4a bf a1 ac 43 7a 94 7b 9f c9 4d 00
bb 93 c0 dd 70 e3 b4 75 b4 3e 33 b5 a0 24 67 d0
a3 52 43 60 89 5c 4b ce b3 be fa 4c 80 6e fa 87
5d bf c9 d6 e7 35 44 36 88 aa ef f8 50 a3 3d 16
bd 12 28 59 8d 0d fa 1d f8 64 03 b4 96 2e ff 56
41 17 93 44 cf 7a 75 42 f9 c8 2d b2 4c 1b 12 35
fb 1d 45 e0 62 5b 1a d1 4b d3 4b 91 94 49 74 4a
24 1e 58 06 d5 06 f2 87 ab eb 44 06 6f 4d 6d d8
6d eb b3 22 68 37 7b 8b cc f5 18 5b 39 1b 8d 07
da 7f 53 a6 99 7e 78 56 64 ad 5c c4 94 a7 d3 3e
a4 c9 d2 37 c6 3c 73 49 60 54 ea 40 ef 41 ff 32
d7 77 6b ab b9 0b bd f7 72 50 fc ca 7a 26 34 43
99 79 60 5f ec 32 3c 0b 51 64 cb 02 03 01 00 01
a3 2a 30 28 30 26 06 03 55 1d 11 04 1f 30 1d a0
1b 06 08 2b 06 01 05 05 07 08 05 a0 0f 0c 0d 2a
2e 31 30 2e 39 30 2e 36 2e 31 34 30 30 0d 06 09
2a 86 48 86 f7 0d 01 01 05 05 00 03 82 01 01 00
70 fe fb a5 9e 0c 6f 51 4c 4e b9 e9 fa 4f 75 b6
ec da 25 c7 e5 c0 13 6e 99 0a 08 67 f9 e1 48 dd
19 62 7d 94 eb 86 bd 41 6d c8 ae e6 06 1b 98 44
77 b6 8c 1a d8 6d bc b0 ee e8 2b bf a8 99 10 2a
ce cc e3 81 ee 0f 7a 41 f6 27 3c c8 9a b9 32 0c
48 7d 33 09 ce af b2 5a 13 01 d0 a7 b4 f9 80 96
20 8b 87 95 cc 67 78 b6 e5 68 6a e5 27 7c 15 39
15 54 b3 82 9e b0 27 c4 fe 72 9e 6b e2 c7 54 5e
41 b3 f6 dc 00 ff 7d 1a 3d 82 cd 8c fc b3 96 8f
f1 f3 46 5e 8d 62 33 3f c2 ab 78 66 b9 00 51 88
ee 0a 2b 99 95 46 9d 4b e8 94 fe f8 e2 39 88 0e
57 30 b0 31 93 89 ed c8 08 05 2e 76 08 92 99 3a
10 40 79 70 b3 e7 70 a3 c6 c4 af 06 60 81 60 64
2f 5b 09 99 f0 d2 fa c0 17 5f ac 85 d5 04 38 e1
6f 8b 7f 97 1f 0d 90 57 e5 df bd 2d 31 f3 55 85
86 d2 6b b0 3a 29 4e 18 e5 b6 a4 b8 3d 5a 0c 7b
0e 00 00 00

TLS GNUTLS: tls_push: 267 bytes

16 03 01 01 06 10 00 01 02 01 00 53 c6 71 b0 a9
e9 9d 5e 73 e6 0a bd 45 e2 88 5b 8b 52 38 d4 4e
6c d4 ef 49 db dd e1 3c 33 65 1b 03 5d 51 36 74
bc d3 7e a8 d2 7b 82 95 4a a4 b8 a3 18 88 4a 5a
68 ac 47 87 3f cd 50 c3 24 c2 43 26 d3 08 06 d1
cd bc 34 c8 bc 67 7d 68 e3 95 b0 51 4c 6e cf 8c
81 6d 48 54 2c 2e 8d 74 1f ac 29 69 c4 8f e7 c6
80 98 7a bb 7b fd 0b 38 10 87 5c 84 23 75 e6 19
0d e2 74 02 17 ff aa b6 81 a8 e7 55 ea e5 b6 ea
87 74 f6 bf 8b 12 4b e4 99 06 3b 06 27 12 e3 16
9a 8b d9 c4 01 ca d2 b3 2f eb 74 11 72 5a 71 9a
a9 80 81 53 bc 12 26 70 17 22 00 da 79 1f 85 f2
16 cf 80 d8 2b d9 8a ba 06 a4 e0 6e f1 9e 93 6f
06 85 65 88 2d 3b 81 e3 3c f2 b4 e5 49 27 9d 67
85 de 89 c4 53 d3 a8 78 b8 15 0d 5f 8f a5 37 c8
92 c2 98 48 17 32 e5 b5 07 25 69 21 6a e8 5a d5
13 9b 26 75 59 a3 33 3e e3 e7 b2

TLS GNUTLS: tls_push: 6 bytes

14 03 01 00 01 01

TLS GNUTLS: tls_push: 45 bytes

16 03 01 00 28 f5 75 44 9f b3 df 21 cf 2f e2 9d
4e 61 b3 b6 4d 0b ca bf 00 42 8d af 0c 37 62 fa
97 58 25 d4 9e e3 e8 a5 cb 12 1d 7d f7

TLS GNUTLS: tls_pull

14 03 01 00 01

TLS GNUTLS: tls_pull

01

TLS GNUTLS: tls_pull

16 03 01 00 28

TLS GNUTLS: tls_pull

09 a7 ef c6 01 2a e8 80 1f 0f 73 30 df 89 44 7f
a8 c6 c2 7c e8 f7 c2 8f f6 9f d7 62 e5 5d e9 e0
47 6c c5 17 e6 3f 8c 58

===> TLS handshake done, send firs message after handshake and waits for
response

TLS GNUTLS: tls_send: [<?xml version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client'
to='10.90.6.140' version='1.0'>] 137 bytes
TLS GNUTLS: tls_push: 253 bytes

17 03 01 00 f8 d4 75 17 4a 71 d4 1b f7 6e 5d 66
32 61 b6 c6 df a0 de 75 2b b9 74 93 52 8e ba ab
7f 66 a2 d4 5c eb 27 c7 03 ba 20 1a d6 7f d2 e9
03 81 ee e5 59 9a 75 0f df 65 ee 0e de af 2f f5
44 f2 7d 18 e7 4a 56 3c ca 21 4f d0 92 8e 71 7c
d8 29 06 88 b0 d0 b0 54 bc a6 0f 7f c3 4d 79 f4
c9 98 f7 b8 53 f0 7f 67 57 e6 d3 3e 0a 70 53 54
c4 bd 9b 39 b6 d9 9f ad 1f aa f9 a0 e3 82 41 ad
43 06 62 7d c8 14 3c 6c 6f bc 3b 54 ab 8e c6 f8
f4 da a5 ab f2 28 c5 22 8f 08 b9 97 35 d5 11 5e
68 3f 03 26 27 37 ba af e5 36 f5 9a 5e 6b a8 8d
5d 02 45 69 5f 42 90 3e c0 f1 ba 60 e0 d3 1d f8
8e 44 5d a8 00 0c ba 48 3e 42 e4 d3 41 be 57 7a
55 4d 5a 35 65 db b0 b9 1c ff 0c a1 3f ca 8c c4
25 42 26 46 ae a5 aa cc ac c7 43 74 41 26 51 c3
45 44 25 c3 68 48 9d 77 bc df af b2 16

SecSEND[<?xml version='1.0'?><stream:stream
xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client'
to='10.90.6.140' version='1.0'>]

===> recieve first message after TLS handshake

TLS GNUTLS: tls_recv
TLS GNUTLS: tls_pull

16 03 01 00 28

TLS GNUTLS: tls_recv: ret: -9 <== GNUTLS_E_UNEXPECTED_PACKET_LENGTH /*
GNUTLS_A_RECORD_OVERFLOW */

Best regards,
   -vitali
-------------- next part --------------
An HTML attachment was scrubbed...
URL: </pipermail/attachments/20120511/56592508/attachment.htm>