my gnutls server's handshake results into -32 (insufficient creds for that request)

Sun Jul 4 19:14:28 CEST 2010

Hey all,

I am about to implement an SSL plugin for my little HTTP server, which
once worked pretty fine, but basic, now I am about to introduce SNI and
all that have to be non-blocking I/O, which made it pretty complicated to
design/implement this feature the generic way.
However, I am now receiving a -32 (GNUTLS_E_INSUFFICIENT_CREDENTIALS),
when calling gnutls_handshake() and I have absolutely no clue what I might
have forgotten to set or register.

As the code is unfortunately not just a 3-liner, I'll provide the debug
output right below:

FYI: I am using the self-signed default certificates for the apache
installation here,
but that shouldn't be the problem. Although, You might encounter the
following names:
- SslDriver: - the GnuTLS I/O driver object, that creates the (ssl) socket
objects
- SslContext: - object that holds the SSL configuration for a specific
(host-)context,
                e.g. x509 cert and key (also in form of gnutls handles)
- SslSocket: - the GnuTLS socket object, that provides my app with
convenient read/write ops and does the handshake stuff, too.
- HttpConnection: the HTTP-connection object

So here we go, with the log:

1278262947.334951: SslContext: SslContext()
1278262947.334951: SslContext: SslContext::setCertFile:
"/etc/ssl/apache2/server.crt"
1278262947.334951: ssl: [2] ASSERT: dn.c:451
1278262947.334951: SslContext: setCertFile: Common Name: "localhost"
1278262947.334951: SslContext: SslContext::setKeyFile:
"/etc/ssl/apache2/server.key"
1278262947.334951: ssl: setupLogLevel(cvar, scope)
1278262947.334951: ssl: setLogLevel: 6
[07/04/2010:19:02:27 +0200] [debug] Enable SSL on host: localhost:8088
1278262947.334951: SslContext: SslContext::setDriver()
1278262947.334951: SslContext: setPriorities: "NORMAL"
[07/04/2010:19:02:27 +0200] [info] Start listening on [0::0]:8089
[07/04/2010:19:02:27 +0200] [info] Start listening on [0::0]:8088 [secure]
[07/04/2010:19:02:27 +0200] [info] Created PID file with value 5631
[/opt/sandbox/var/run/x0d.pid]
1278262950.682260: SslSocket: SslSocket()
1278262950.682260: HttpConnection: HttpConnection(0x1c326c0): fd=12
1278262950.682260: SslSocket: handshake()
1278262950.682260: ssl: [4] REC[0x1c46f00]: Expected Packet[0]
Handshake(22) with length: 1
1278262950.682260: ssl: [4] REC[0x1c46f00]: Received Packet[0]
Handshake(22) with length: 132
1278262950.682260: ssl: [4] REC[0x1c46f00]: Decrypted Packet[0]
Handshake(22) with length: 132
1278262950.682260: ssl: [6] BUF[HSK]: Inserted 132 bytes of Data(22)
1278262950.682260: ssl: [6] BUF[REC][HD]: Read 1 bytes of Data(22)
1278262950.682260: ssl: [6] BUF[REC][HD]: Read 3 bytes of Data(22)
1278262950.682260: ssl: [3] HSK[0x1c46f00]: CLIENT HELLO was received [132
bytes]
1278262950.682260: ssl: [6] BUF[REC][HD]: Read 128 bytes of Data(22)
1278262950.682260: ssl: [6] BUF[HSK]: Inserted 4 bytes of Data
1278262950.682260: ssl: [6] BUF[HSK]: Inserted 128 bytes of Data
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Client's version: 3.3
1278262950.682260: ssl: [2] ASSERT: gnutls_db.c:326
1278262950.682260: ssl: [2] ASSERT: gnutls_db.c:246
1278262950.682260: ssl: [2] EXT[0x1c46f00]: Found extension 'SERVER_NAME/0'
1278262950.682260: ssl: [2] EXT[0x1c46f00]: Found extension
'SAFE_RENEGOTIATION/65281'
1278262950.682260: ssl: [2] EXT[0x1c46f00]: Found extension
'SIGNATURE_ALGORITHMS/13'
1278262950.682260: SslSocket: onClientHello()
1278262950.682260: SslSocket: onClientHello: SNI Name: "localhost"
1278262950.682260: SslContext: bind()
1278262950.682260: ssl: [2] EXT[0x1c46f00]: Found extension 'SERVER_NAME/0'
1278262950.682260: ssl: [2] EXT[0x1c46f00]: Found extension
'SAFE_RENEGOTIATION/65281'
1278262950.682260: ssl: [2] EXT[0x1c46f00]: Found extension
'SIGNATURE_ALGORITHMS/13'
1278262950.682260: ssl: [2] EXT[0x1c46f00]: Found extension 'SERVER_NAME/0'
1278262950.682260: ssl: [2] EXT[0x1c46f00]: Found extension
'SAFE_RENEGOTIATION/65281'
1278262950.682260: ssl: [2] EXT[0x1c46f00]: Found extension
'SIGNATURE_ALGORITHMS/13'
1278262950.682260: SslContext: onRetrieveCert()
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
PSK_SHA_ARCFOUR_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
PSK_SHA_3DES_EDE_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
PSK_SHA_AES_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
PSK_SHA_AES_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_PSK_SHA_ARCFOUR_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_PSK_SHA_3DES_EDE_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_PSK_SHA_AES_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_PSK_SHA_AES_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
SRP_SHA_3DES_EDE_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
SRP_SHA_AES_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
SRP_SHA_AES_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
SRP_SHA_DSS_3DES_EDE_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
SRP_SHA_RSA_3DES_EDE_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
SRP_SHA_DSS_AES_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
SRP_SHA_RSA_AES_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
SRP_SHA_DSS_AES_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
SRP_SHA_RSA_AES_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_DSS_ARCFOUR_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_DSS_3DES_EDE_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_DSS_AES_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_DSS_AES_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_DSS_CAMELLIA_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_DSS_CAMELLIA_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_DSS_AES_128_CBC_SHA256
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Removing ciphersuite:
DHE_DSS_AES_256_CBC_SHA256
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
DHE_RSA_3DES_EDE_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
DHE_RSA_AES_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
DHE_RSA_AES_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
DHE_RSA_CAMELLIA_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
DHE_RSA_CAMELLIA_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
DHE_RSA_AES_128_CBC_SHA256
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
DHE_RSA_AES_256_CBC_SHA256
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
RSA_ARCFOUR_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
RSA_ARCFOUR_MD5
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
RSA_3DES_EDE_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
RSA_AES_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
RSA_AES_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
RSA_CAMELLIA_128_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
RSA_CAMELLIA_256_CBC_SHA1
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
RSA_AES_128_CBC_SHA256
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Keeping ciphersuite:
RSA_AES_256_CBC_SHA256
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Selected cipher suite:
DHE_RSA_AES_128_CBC_SHA256
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Selected Compression Method: NULL
1278262950.682260: ssl: [3] HSK[0x1c46f00]: Safe renegotiation succeeded
1278262950.682260: ssl: [2] EXT[0x1c46f00]: Sending extension
SAFE_RENEGOTIATION
1278262950.682260: ssl: [3] HSK[0x1c46f00]: SessionID:
9b6c855caf8abf3778010fcfaff409ffcc1c4e94128a9018bd3f6a3fd1e357d4
1278262950.682260: ssl: [3] HSK[0x1c46f00]: SERVER HELLO was sent [81 bytes]
1278262950.682260: ssl: [6] BUF[HSK]: Peeked 132 bytes of Data
1278262950.682260: ssl: [6] BUF[HSK]: Emptied buffer
1278262950.682260: ssl: [4] REC[0x1c46f00]: Sending Packet[0]
Handshake(22) with length: 81
1278262950.682260: ssl: [4] REC[0x1c46f00]: Sent Packet[1] Handshake(22)
with length: 86
1278262950.682260: ssl: [3] HSK[0x1c46f00]: CERTIFICATE was sent [739 bytes]
1278262950.682260: ssl: [6] BUF[HSK]: Peeked 0 bytes of Data
1278262950.682260: ssl: [6] BUF[HSK]: Emptied buffer
1278262950.682260: ssl: [4] REC[0x1c46f00]: Sending Packet[1]
Handshake(22) with length: 739
1278262950.682260: ssl: [4] REC[0x1c46f00]: Sent Packet[2] Handshake(22)
with length: 744
1278262950.682260: ssl: [2] ASSERT: gnutls_sig.c:223
1278262950.682260: ssl: [2] ASSERT: auth_dhe.c:156
1278262950.682260: ssl: [2] ASSERT: gnutls_kx.c:218
1278262950.682260: ssl: [2] ASSERT: gnutls_handshake.c:3029
1278262950.682260: ssl: [6] BUF[HSK]: Cleared Data from buffer
1278262950.682260: SslSocket: SSL handshake failed (-32): Insufficient
credentials for that request.

This is the backtrace that caused the -32:

#0  _gnutls_tls_sign (session=0x674140, cert=0x627480, pkey=0x0,
hash_concat=0x7fffffffd440, signature=0x7fffffffd4b0) at gnutls_sig.c:297
#1  0x00007ffff634ecac in _gnutls_handshake_sign_data (session=0x674140,
cert=0x627480, pkey=0x0, params=0x7fffffffd4a0, signature=0x7fffffffd4b0,
sign_algo=0x7fffffffd49c) at gnu
tls_sig.c:220
#2  0x00007ffff6350526 in gen_dhe_server_kx (session=0x674140,
data=0x7fffffffd540) at auth_dhe.c:151
#3  0x00007ffff6337682 in _gnutls_send_server_kx_message
(session=0x674140, again=0) at gnutls_kx.c:206
#4  0x00007ffff633325f in _gnutls_handshake_server (session=0x674140) at
gnutls_handshake.c:3027
#5  0x00007ffff63323c3 in gnutls_handshake (session=0x674140) at
gnutls_handshake.c:2703
#6  0x00007ffff7b655c9 in x0::SslSocket::handshake (this=0x6701d0) at
/home/trapni/projects/x0/src/x0/SslSocket.cpp:88
#7  0x00007ffff7b70ea7 in x0::HttpConnection::start (this=0x670000) at
/home/trapni/projects/x0/src/x0/http/HttpConnection.cpp:211
#8  0x00007ffff7b843b3 in x0::HttpListener::callback (this=0x659760,
watcher=..., revents=1) at
/home/trapni/projects/x0/src/x0/http/HttpListener.cpp:163
#9  0x00007ffff7b8470d in ev::base<ev_io,
ev::io>::method_thunk<x0::HttpListener,
&(x0::HttpListener::callback(ev::io&, int))> (loop=0x7ffff6a02360,
w=0x659760, revents=1) at /usr
/include/ev++.h:469
#10 0x00007ffff67f8880 in ev_invoke_pending (loop=0x7ffff6a02360) at
ev.c:1997
#11 0x00007ffff67fd8c2 in ev_loop (loop=0x7ffff6a02360, flags=2) at ev.c:2359
#12 0x00007ffff7b96d14 in x0::HttpServer::run (this=0x7fffffffda38) at
/home/trapni/projects/x0/src/x0/http/HttpServer.cpp:355
#13 0x00000000004108a9 in x0d::_run (this=0x7fffffffd9f0) at
/home/trapni/projects/x0/src/x0d.cpp:317
#14 0x0000000000410574 in x0d::run (this=0x7fffffffd9f0) at
/home/trapni/projects/x0/src/x0d.cpp:214
#15 0x000000000040e12c in main (argc=1, argv=0x7fffffffdf88) at
/home/trapni/projects/x0/src/x0d.cpp:541

Unfortunately, I have absolutely no idea in what I did wrong,
but I hope I spend enough information for you, to help me out a little :)

Best regards,
Christian Parpart.