IMAP/SSL issue

Good evening,

I’m trying to get the IMAP/SSL module working and running into an odd
issue.
Plaintext connections work just fine, but SSL connections don’t seem to
contact
the auth daemon.

imtest -p 143 -a $USER -m login localhost

S: * OK IMAP4 ready
C: C01 CAPABILITY
S: * CAPABILITY IMAP4rev1 UIDPLUS SORT AUTH=PLAIN
S: C01 OK completed
Please enter your password:
C: L01 LOGIN $USER {8}
S: + OK
C:
S: L01 OK User logged in
Authenticated.
Security strength factor: 0

imtest -s -p 993 -a $USER -m login localhost

verify error:num=20:unable to get local issuer certificate
verify error:num=27:certificate not trusted
verify error:num=21:unable to verify the first certificate
TLS connection established: TLSv1 with cipher DHE-RSA-AES256-SHA
(256/256 bits)
S: * OK IMAP4 ready
C: C01 CAPABILITY
failure: prot layer failure

2008/07/28 20:14:52 [notice] 422#0: using the “/dev/poll” event method
2008/07/28 20:14:52 [notice] 422#0: nginx/0.7.6
2008/07/28 20:14:52 [notice] 422#0: built by gcc 3.4.3
(csl-sol210-3_4-branch+sol_rpath)
2008/07/28 20:14:52 [notice] 422#0: OS: SunOS 5.10
2008/07/28 20:14:52 [notice] 422#0: version: Generic_127112-03
2008/07/28 20:14:52 [notice] 422#0: getrlimit(RLIMIT_NOFILE): 1024:1024
2008/07/28 20:14:52 [notice] 422#0: start worker processes
2008/07/28 20:14:52 [notice] 422#0: start worker process 423
2008/07/28 20:15:14 [debug] 423#0: *1 accept: 127.0.0.1 fd:10
2008/07/28 20:15:14 [debug] 423#0: malloc: 000000000062DFE0:328
2008/07/28 20:15:14 [info] 423#0: *1 client 127.0.0.1 connected to
0.0.0.0:993
2008/07/28 20:15:14 [debug] 423#0: *1 SSL_do_handshake: -1
2008/07/28 20:15:14 [debug] 423#0: *1 SSL_get_error: 2
2008/07/28 20:15:14 [debug] 423#0: *1 devpoll add event: fd:10 ev:0001
2008/07/28 20:15:14 [debug] 423#0: *1 devpoll fd:10 ev:0001 fl:0000
2008/07/28 20:15:14 [debug] 423#0: *1 event timer add: 10:
60000:1217290574610
2008/07/28 20:15:14 [debug] 423#0: *1 SSL handshake handler: 0
2008/07/28 20:15:14 [debug] 423#0: *1 SSL_do_handshake: -1
2008/07/28 20:15:14 [debug] 423#0: *1 SSL_get_error: 2
2008/07/28 20:15:14 [debug] 423#0: *1 SSL handshake handler: 0
2008/07/28 20:15:14 [debug] 423#0: *1 http ssl new session:
ADF535E5:32:119
2008/07/28 20:15:14 [debug] 423#0: *1 SSL_do_handshake: 1
2008/07/28 20:15:14 [debug] 423#0: *1 devpoll del event: fd:10 ev:0001
2008/07/28 20:15:14 [debug] 423#0: *1 devpoll fd:10 ev:0800 fl:0000
2008/07/28 20:15:14 [debug] 423#0: *1 SSL: TLSv1, cipher:
“DHE-RSA-AES256-SHA SSLv3 Kx=DH Au=RSA Enc=AES(256) Mac=SHA1”
2008/07/28 20:15:14 [debug] 423#0: *1 malloc: 000000000062A400:256
2008/07/28 20:15:14 [debug] 423#0: *1 event timer: 10, old:
1217290574610, new: 1217290574641
2008/07/28 20:15:14 [debug] 423#0: *1 SSL to write: 18
2008/07/28 20:15:14 [debug] 423#0: *1 SSL_write: 18
2008/07/28 20:16:14 [debug] 423#0: *1 event timer del: 10: 1217290574610
2008/07/28 20:16:14 [info] 423#0: *1 client timed out (145: Connection
timed out) while in auth state, client: 127.0.0.1, server: 0.0.0.0:993
2008/07/28 20:16:14 [debug] 423#0: *1 close mail connection: 10
2008/07/28 20:16:14 [debug] 423#0: *1 SSL_shutdown: 1
2008/07/28 20:16:14 [debug] 423#0: *1 free: 000000000062DFE0
2008/07/28 20:16:14 [debug] 423#0: *1 free: 00000000006050F0, unused: 8
2008/07/28 20:16:14 [debug] 423#0: *1 free: 000000000062A400, unused:
176

/opt/local/nginx/sbin/nginx -V

nginx version: nginx/0.7.6
built by gcc 3.4.3 (csl-sol210-3_4-branch+sol_rpath)
configure arguments: --prefix=/opt/local/nginx
–pid-path=/var/run/nginx.pid --error-log-path=/var/log/nginx/error.log
–http-log-path=/var/log/nginx/access.log --with-http_ssl_module
–with-openssl=/export/scratch/openssl-0.9.8h --with-cc-opt=-m64
-I/usr/local/include -I/usr/local/ssl/include --with-ld-opt=-L/lib/64
-L/usr/sfw/lib/64 -R/usr/sfw/lib/64 -R/lib/64 -L/usr/local/ssl/lib -m64
-L/usr/local/lib -R/usr/local/lib --with-mail --with-mail_ssl_module
–with-debug

My config:

worker_processes 1;
events {
worker_connections 256;
multi_accept on;
debug_connection 127.0.0.1;
}

mail {
auth_http 127.0.0.1:9000/auth;

imap_capabilities  "IMAP4rev1" "UIDPLUS" "SORT";

server {
    listen     143;
    protocol   imap;
    proxy      on;
}

server {
    listen    993;
    protocol  imap;
    proxy     on;
    ssl       on;
    ssl_certificate /tmp/cert.crt;
    ssl_certificate_key /tmp/cert.key;
    starttls  on;
}

}

Running errinfo from the DTrace Toolkit gets me this:

./errinfo -n nginx

        EXEC          SYSCALL  ERR  DESC
       nginx             read   11  Resource temporarily unavailable
       nginx           accept   11  Resource temporarily unavailable
       nginx             read   11  Resource temporarily unavailable

But that may be a red herring…

I haven’t been able to find anything in the archives, nor has anyone on
IRC
been able to shed any light on what I’ve mucked up.

Thoughts?

Thanks much.

On Tue, Jul 29, 2008 at 12:16:29AM -0400, Bryan Allen wrote:

C: L01 LOGIN $USER {8}
TLS connection established: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)
2008/07/28 20:14:52 [notice] 422#0: start worker processes
2008/07/28 20:15:14 [debug] 423#0: *1 SSL_do_handshake: -1
2008/07/28 20:15:14 [debug] 423#0: *1 SSL_write: 18
2008/07/28 20:16:14 [debug] 423#0: *1 event timer del: 10: 1217290574610
2008/07/28 20:16:14 [info] 423#0: *1 client timed out (145: Connection timed out) while in auth state, client: 127.0.0.1, server: 0.0.0.0:993
2008/07/28 20:16:14 [debug] 423#0: *1 close mail connection: 10
2008/07/28 20:16:14 [debug] 423#0: *1 SSL_shutdown: 1
2008/07/28 20:16:14 [debug] 423#0: *1 free: 000000000062DFE0
2008/07/28 20:16:14 [debug] 423#0: *1 free: 00000000006050F0, unused: 8
2008/07/28 20:16:14 [debug] 423#0: *1 free: 000000000062A400, unused: 176

The attached patch should fix the bug.

±-----------------------------------------------------------------------------
| On 2008-07-29 13:00:52, Igor S. wrote:
|
| The attached patch should fix the bug.

Patch applied, but I’m afraid the behavior persists. Is there
anything I could provide which would make it easier to debug?

Thanks very much for your help.

On Tue, Jul 29, 2008 at 11:58:06AM -0400, Bryan Allen wrote:

±-----------------------------------------------------------------------------
| On 2008-07-29 13:00:52, Igor S. wrote:
|
| The attached patch should fix the bug.

Patch applied, but I’m afraid the behavior persists. Is there
anything I could provide which would make it easier to debug?

Could you send debug log to me ?

±-----------------------------------------------------------------------------
| On 2008-07-29 20:00:19, Igor S. wrote:
|
| Could you send debug log to me ?

Just to ensure I’m not being stupid… nginx proxying IMAP-SSL is going
to run
cleartext to the auth backend, and then cleartext to the actual IMAP
daemon,
right? I’ve confirmed (I believe) through tracing the auth and IMAP
daemons
that they aren’t getting any connections from nginx… so I’m not sure
where
it’s hanging, exactly.

Again, thanks for the help!

2008/07/29 12:30:08 [notice] 23220#0: start worker processes
2008/07/29 12:30:08 [debug] 23220#0: channel 8:7
2008/07/29 12:30:08 [notice] 23220#0: start worker process 23221
2008/07/29 12:30:08 [debug] 23220#0: sigsuspend
2008/07/29 12:30:08 [debug] 23221#0: malloc: 0000000000604EB0:256
2008/07/29 12:30:08 [debug] 23221#0: malloc: 0000000000604FC0:256
2008/07/29 12:30:08 [debug] 23221#0: malloc: 00000000006050D0:256
2008/07/29 12:30:08 [debug] 23221#0: malloc: 0000000000625600:8192
2008/07/29 12:30:08 [debug] 23221#0: malloc: 000000000062DF60:40960
2008/07/29 12:30:08 [debug] 23221#0: malloc: 0000000000637F70:26624
2008/07/29 12:30:08 [debug] 23221#0: malloc: 000000000063E780:26624
2008/07/29 12:30:08 [debug] 23221#0: devpoll add event: fd:4 ev:0001
2008/07/29 12:30:08 [debug] 23221#0: devpoll fd:4 ev:0001 fl:0000
2008/07/29 12:30:08 [debug] 23221#0: devpoll add event: fd:5 ev:0001
2008/07/29 12:30:08 [debug] 23221#0: devpoll fd:5 ev:0001 fl:0000
2008/07/29 12:30:08 [debug] 23221#0: devpoll add event: fd:7 ev:0001
2008/07/29 12:30:08 [debug] 23221#0: devpoll fd:7 ev:0001 fl:0000
2008/07/29 12:30:08 [debug] 23221#0: setproctitle: "nginx: worker
process (/opt/local/nginx/sbin/nginx)
"
2008/07/29 12:30:08 [debug] 23221#0: worker cycle
2008/07/29 12:30:08 [debug] 23221#0: devpoll timer: -1
2008/07/29 12:32:39 [debug] 23221#0: devpoll: fd:5, ev:0001, rev:0001
2008/07/29 12:32:39 [debug] 23221#0: accept on 0.0.0.0:993, ready: 1
2008/07/29 12:32:39 [debug] 23221#0: malloc: 0000000000602690:256
2008/07/29 12:32:39 [debug] 23221#0: *1 accept: 127.0.0.1 fd:8
2008/07/29 12:32:39 [debug] 23221#0: malloc: 00000000006027A0:328
2008/07/29 12:32:39 [info] 23221#0: *1 client 127.0.0.1 connected to
0.0.0.0:993
2008/07/29 12:32:39 [debug] 23221#0: *1 SSL_do_handshake: -1
2008/07/29 12:32:39 [debug] 23221#0: *1 SSL_get_error: 2
2008/07/29 12:32:39 [debug] 23221#0: *1 devpoll add event: fd:8 ev:0001
2008/07/29 12:32:39 [debug] 23221#0: *1 devpoll fd:8 ev:0001 fl:0000
2008/07/29 12:32:39 [debug] 23221#0: *1 event timer add: 8:
60000:1217349219366
2008/07/29 12:32:39 [debug] 23221#0: accept() not ready (11: Resource
temporarily unavailable)
2008/07/29 12:32:39 [debug] 23221#0: timer delta: 150680
2008/07/29 12:32:39 [debug] 23221#0: posted events 0000000000000000
2008/07/29 12:32:39 [debug] 23221#0: worker cycle
2008/07/29 12:32:39 [debug] 23221#0: devpoll timer: 60000
2008/07/29 12:32:39 [debug] 23221#0: devpoll: fd:8, ev:0001, rev:0001
2008/07/29 12:32:39 [debug] 23221#0: *1 SSL handshake handler: 0
2008/07/29 12:32:39 [debug] 23221#0: *1 SSL_do_handshake: -1
2008/07/29 12:32:39 [debug] 23221#0: *1 SSL_get_error: 2
2008/07/29 12:32:39 [debug] 23221#0: timer delta: 5
2008/07/29 12:32:39 [debug] 23221#0: posted events 0000000000000000
2008/07/29 12:32:39 [debug] 23221#0: worker cycle
2008/07/29 12:32:39 [debug] 23221#0: devpoll timer: 59995
2008/07/29 12:32:39 [debug] 23221#0: devpoll: fd:8, ev:0001, rev:0001
2008/07/29 12:32:39 [debug] 23221#0: *1 SSL handshake handler: 0
2008/07/29 12:32:39 [debug] 23221#0: slab alloc: 119 slot: 4
2008/07/29 12:32:39 [debug] 23221#0: slab alloc: FFFFFD7FFEE50080
2008/07/29 12:32:39 [debug] 23221#0: slab alloc: 128 slot: 4
2008/07/29 12:32:39 [debug] 23221#0: slab alloc: FFFFFD7FFEE50100
2008/07/29 12:32:39 [debug] 23221#0: *1 http ssl new session:
533181D2:32:119
2008/07/29 12:32:39 [debug] 23221#0: *1 SSL_do_handshake: 1
2008/07/29 12:32:39 [debug] 23221#0: *1 devpoll del event: fd:8 ev:0001
2008/07/29 12:32:39 [debug] 23221#0: *1 devpoll fd:8 ev:0800 fl:0000
2008/07/29 12:32:39 [debug] 23221#0: *1 SSL: TLSv1, cipher:
“DHE-RSA-AES256-SHA SSLv3 Kx=DH Au=RSA Enc=AES(256) Mac=SHA1”
2008/07/29 12:32:39 [debug] 23221#0: *1 malloc: 0000000000629140:256
2008/07/29 12:32:39 [debug] 23221#0: *1 event timer: 8, old:
1217349219366, new: 1217349219399
2008/07/29 12:32:39 [debug] 23221#0: *1 SSL to write: 18
2008/07/29 12:32:39 [debug] 23221#0: *1 SSL_write: 18
2008/07/29 12:32:39 [debug] 23221#0: timer delta: 28
2008/07/29 12:32:39 [debug] 23221#0: posted events 0000000000000000
2008/07/29 12:32:39 [debug] 23221#0: worker cycle
2008/07/29 12:32:39 [debug] 23221#0: devpoll timer: 59967
2008/07/29 12:33:39 [debug] 23221#0: timer delta: 59971
2008/07/29 12:33:39 [debug] 23221#0: *1 event timer del: 8:
1217349219366
2008/07/29 12:33:39 [info] 23221#0: *1 client timed out (145: Connection
timed out) while in auth state, client: 127.0.0.1, server: 0.0.0.0:993
2008/07/29 12:33:39 [debug] 23221#0: *1 close mail connection: 8
2008/07/29 12:33:39 [debug] 23221#0: *1 SSL_shutdown: 1
2008/07/29 12:33:39 [debug] 23221#0: *1 free: 00000000006027A0
2008/07/29 12:33:39 [debug] 23221#0: *1 free: 0000000000602690, unused:
8
2008/07/29 12:33:39 [debug] 23221#0: *1 free: 0000000000629140, unused:
176
2008/07/29 12:33:39 [debug] 23221#0: posted events 0000000000000000
2008/07/29 12:33:39 [debug] 23221#0: worker cycle
2008/07/29 12:33:39 [debug] 23221#0: devpoll timer: -1

On Tue, Jul 29, 2008 at 12:38:26PM -0400, Bryan Allen wrote:

±-----------------------------------------------------------------------------
| On 2008-07-29 20:00:19, Igor S. wrote:
|
| Could you send debug log to me ?

Just to ensure I’m not being stupid… nginx proxying IMAP-SSL is going to run
cleartext to the auth backend, and then cleartext to the actual IMAP daemon,
right? I’ve confirmed (I believe) through tracing the auth and IMAP daemons
that they aren’t getting any connections from nginx… so I’m not sure where
it’s hanging, exactly.

Yes, nginx speaks in clear text with both auth backend and IMAP backend.

Back out the previous patch and try the new one.

±-----------------------------------------------------------------------------
| On 2008-07-29 21:17:46, Igor S. wrote:
|
| Back out the previous patch and try the new one.

Awesome! Works.

Thanks very much.