Problems with imap proxy sending invalid username

Pat nginx at brokenwatch.net
Wed Jul 14 18:28:50 MSD 2010 

Hello,

New user of nginx, trying to get started. I set up a php authentication 
script. Whenever I login it seems to pass on the wrong username and does 
not send any password at all.

For troubleshooting purposes my php script looks like this:

<?php
header("Auth-Status: OK");
header("Auth-Server: 10.0.7.134"); //my imap server that we are proxying to
header("Auth-Port: 143");
header("Auth-User: trashcan"); //tried removing this also
header("Content-type: txt/html"); //saw that the perl auth module sends 
this, did not help
?>

My config file:
#user nobody;
worker_processes 1;
error_log logs/error.log debug;
pid logs/nginx.pid;

events {
worker_connections 1024;
multi_accept on;
}

mail {
auth_http 10.0.5.61:80/mail/auth.php;
imap_capabilities "IMAP4rev1" "UIDPLUS";

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


Relevant debug output:
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http process status line
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http process headers
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header: "Date: 
Wed, 14 Jul 2010 14:03:42 GMT"
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header: "Server: 
Apache/2.2.3 (CentOS)"
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header: 
"X-Powered-By: PHP/5.1.6"
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header: 
"Auth-Status: OK"
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header: 
"Auth-Server: 10.0.7.134"
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header: 
"Auth-Port: 143"
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header: 
"Auth-User: trashcan"
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header: 
"Content-Length: 0"
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header: 
"Connection: close"
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header: 
"Content-Type: txt/html"
2010/07/14 09:03:42 [debug] 22837#0: *4 mail auth http header done

2010/07/14 09:03:42 [debug] 22837#0: *4 ngx_imap_start: line.data: a001 
LOGIN {8}
�0R
2010/07/14 09:03:42 [debug] 22837#0: *4 send: fd:8 16 of 16
2010/07/14 09:03:42 [debug] 22837#0: *4 mail proxy dummy handler

2010/07/14 09:03:42 [debug] 22837#0: *4 mail proxy imap auth handler
2010/07/14 09:03:42 [debug] 22837#0: *4 recv: fd:8 23 of 4096
2010/07/14 09:03:42 [error] 22837#0: *4 upstream sent invalid response: 
"a001 NO Login failed." while reading response from upstream, client: 
10.2.5.60, server: 0.0.0.0:143, login: "trashcan", upstream: 10.0.7.134:143

nginx version: nginx/0.7.67

Full debug logs:

2010/07/14 09:23:24 [debug] 23091#0: bind() 0.0.0.0:143 #5
2010/07/14 09:23:24 [notice] 23091#0: using the "epoll" event method
2010/07/14 09:23:24 [debug] 23091#0: counter: 00002B81D0D4F080, 1
2010/07/14 09:23:24 [notice] 23091#0: nginx/0.7.67
2010/07/14 09:23:24 [notice] 23091#0: built by gcc 4.1.2 20080704 (Red 
Hat 4.1.2-48)
2010/07/14 09:23:24 [notice] 23091#0: OS: Linux 2.6.18-194.8.1.el5
2010/07/14 09:23:24 [notice] 23091#0: getrlimit(RLIMIT_NOFILE): 1024:1024
2010/07/14 09:23:24 [debug] 23092#0: write: 6, 00007FFF8FFF1AE0, 6, 0
2010/07/14 09:23:24 [debug] 23092#0: setproctitle: "nginx: master 
process /usr/local/nginx/sbin/nginx"
2010/07/14 09:23:24 [notice] 23092#0: start worker processes
2010/07/14 09:23:24 [debug] 23092#0: channel 3:6
2010/07/14 09:23:24 [debug] 23093#0: malloc: 0000000006A123A0:6144
2010/07/14 09:23:24 [debug] 23093#0: malloc: 00002B81D0D61010:180224
2010/07/14 09:23:24 [debug] 23093#0: malloc: 0000000006A179E0:106496
2010/07/14 09:23:24 [debug] 23093#0: malloc: 0000000006A319F0:106496
2010/07/14 09:23:24 [debug] 23093#0: epoll add event: fd:5 op:1 ev:00000001
2010/07/14 09:23:24 [debug] 23093#0: epoll add event: fd:6 op:1 ev:00000001
2010/07/14 09:23:24 [debug] 23093#0: setproctitle: "nginx: worker process"
2010/07/14 09:23:24 [notice] 23092#0: start worker process 23093
2010/07/14 09:23:24 [debug] 23092#0: sigsuspend
2010/07/14 09:23:24 [debug] 23093#0: worker cycle
2010/07/14 09:23:24 [debug] 23093#0: epoll timer: -1
2010/07/14 09:24:50 [debug] 23093#0: epoll: fd:5 ev:0001 d:00002B81D0D61010
2010/07/14 09:24:50 [debug] 23093#0: accept on 0.0.0.0:143, ready: 1
2010/07/14 09:24:50 [debug] 23093#0: malloc: 0000000006A0DB40:256
2010/07/14 09:24:50 [debug] 23093#0: *1 accept: 10.2.5.60 fd:3
2010/07/14 09:24:50 [debug] 23093#0: malloc: 0000000006A0DD90:360
2010/07/14 09:24:50 [info] 23093#0: *1 client 10.2.5.60 connected to 
0.0.0.0:143
2010/07/14 09:24:50 [debug] 23093#0: *1 event timer add: 3: 
60000:1279117550641
2010/07/14 09:24:50 [debug] 23093#0: *1 epoll add event: fd:3 op:1 
ev:80000001
2010/07/14 09:24:50 [debug] 23093#0: *1 send: fd:3 18 of 18
2010/07/14 09:24:50 [debug] 23093#0: accept() not ready (11: Resource 
temporarily unavailable)
2010/07/14 09:24:50 [debug] 23093#0: timer delta: 86304
2010/07/14 09:24:50 [debug] 23093#0: posted events 0000000000000000
2010/07/14 09:24:50 [debug] 23093#0: worker cycle
2010/07/14 09:24:50 [debug] 23093#0: epoll timer: 60000
2010/07/14 09:25:09 [debug] 23093#0: epoll: fd:3 ev:0001 d:00002B81D0D61170
2010/07/14 09:25:09 [debug] 23093#0: *1 malloc: 0000000006A13BB0:256
2010/07/14 09:25:09 [debug] 23093#0: *1 malloc: 0000000006A13CC0:4096
2010/07/14 09:25:09 [debug] 23093#0: *1 imap auth state
2010/07/14 09:25:09 [debug] 23093#0: *1 recv: fd:3 28 of 4096
2010/07/14 09:25:09 [debug] 23093#0: *1 imap auth command: 1
2010/07/14 09:25:09 [debug] 23093#0: *1 imap login:"trashcan"
2010/07/14 09:25:09 [debug] 23093#0: *1 event timer del: 3: 1279117550641
2010/07/14 09:25:09 [debug] 23093#0: *1 malloc: 0000000006A14CD0:2048
2010/07/14 09:25:09 [debug] 23093#0: *1 socket 8
2010/07/14 09:25:09 [debug] 23093#0: *1 epoll add connection: fd:8 
ev:80000005
2010/07/14 09:25:09 [debug] 23093#0: *1 connect to 10.0.5.61:80, fd:8 #2
2010/07/14 09:25:09 [debug] 23093#0: *1 event timer add: 8: 
60000:1279117569461
2010/07/14 09:25:09 [debug] 23093#0: *1 event timer add: 8: 
60000:1279117569461
2010/07/14 09:25:09 [debug] 23093#0: timer delta: 18820
2010/07/14 09:25:09 [debug] 23093#0: posted events 0000000000000000
2010/07/14 09:25:09 [debug] 23093#0: worker cycle
2010/07/14 09:25:09 [debug] 23093#0: epoll timer: 60000
2010/07/14 09:25:09 [debug] 23093#0: epoll: fd:8 ev:0004 d:00002B81D0D61220
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http write handler
2010/07/14 09:25:09 [debug] 23093#0: *1 send: fd:8 174 of 174
2010/07/14 09:25:09 [debug] 23093#0: *1 event timer del: 8: 1279117569461
2010/07/14 09:25:09 [debug] 23093#0: timer delta: 0
2010/07/14 09:25:09 [debug] 23093#0: posted events 0000000000000000
2010/07/14 09:25:09 [debug] 23093#0: worker cycle
2010/07/14 09:25:09 [debug] 23093#0: epoll timer: 60000
2010/07/14 09:25:09 [debug] 23093#0: epoll: fd:8 ev:0005 d:00002B81D0D61220
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http read handler
2010/07/14 09:25:09 [debug] 23093#0: *1 recv: fd:8 232 of 1024
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http process status line
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http process headers
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http header: "Date: 
Wed, 14 Jul 2010 14:25:09 GMT"
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http header: "Server: 
Apache/2.2.3 (CentOS)"
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http header: 
"X-Powered-By: PHP/5.1.6"2010/07/14 09:25:09 [debug] 23093#0: *1 mail 
auth http header: "Auth-Status: OK"
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http header: 
"Auth-Server: 10.0.7.134"
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http header: 
"Auth-Port: 143"
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http header: 
"Content-Length: 0"
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http header: 
"Connection: close"
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http header: 
"Content-Type: txt/html"
2010/07/14 09:25:09 [debug] 23093#0: *1 mail auth http header done
2010/07/14 09:25:09 [debug] 23093#0: *1 event timer del: 8: 1279117569461
2010/07/14 09:25:09 [debug] 23093#0: *1 free: 0000000006A14CD0, unused: 264
2010/07/14 09:25:09 [debug] 23093#0: *1 malloc: 0000000006A14CD0:256
2010/07/14 09:25:09 [debug] 23093#0: *1 socket 8
2010/07/14 09:25:09 [debug] 23093#0: *1 epoll add connection: fd:8 
ev:80000005
2010/07/14 09:25:09 [debug] 23093#0: *1 connect to 10.0.7.134:143, fd:8 #3
2010/07/14 09:25:09 [debug] 23093#0: *1 event timer add: 8: 
60000:1279117569461
2010/07/14 09:25:09 [debug] 23093#0: *1 malloc: 0000000006A14DE0:4096
2010/07/14 09:25:09 [debug] 23093#0: *1 mail proxy dummy handler
2010/07/14 09:25:09 [debug] 23093#0: timer delta: 0
2010/07/14 09:25:09 [debug] 23093#0: posted events 0000000000000000
2010/07/14 09:25:09 [debug] 23093#0: worker cycle
2010/07/14 09:25:09 [debug] 23093#0: epoll timer: 60000
2010/07/14 09:25:09 [debug] 23093#0: epoll: fd:8 ev:0004 d:00002B81D0D61221
2010/07/14 09:25:09 [debug] 23093#0: *1 mail proxy dummy handler
2010/07/14 09:25:09 [debug] 23093#0: timer delta: 2
2010/07/14 09:25:09 [debug] 23093#0: posted events 0000000000000000
2010/07/14 09:25:09 [debug] 23093#0: worker cycle
2010/07/14 09:25:09 [debug] 23093#0: epoll timer: 59998
2010/07/14 09:25:09 [debug] 23093#0: epoll: fd:8 ev:0005 d:00002B81D0D61221
2010/07/14 09:25:09 [debug] 23093#0: *1 mail proxy imap auth handler
2010/07/14 09:25:09 [debug] 23093#0: *1 recv: fd:8 226 of 4096
2010/07/14 09:25:09 [debug] 23093#0: *1 ngx_imap_start: mail proxy send 
login
2010/07/14 09:25:09 [debug] 23093#0: *1 send: fd:8 16 of 16
2010/07/14 09:25:09 [debug] 23093#0: *1 mail proxy dummy handler
2010/07/14 09:25:09 [debug] 23093#0: timer delta: 0
2010/07/14 09:25:09 [debug] 23093#0: posted events 0000000000000000
2010/07/14 09:25:09 [debug] 23093#0: worker cycle
2010/07/14 09:25:09 [debug] 23093#0: epoll timer: 59998
2010/07/14 09:25:09 [debug] 23093#0: epoll: fd:8 ev:0005 d:00002B81D0D61221
2010/07/14 09:25:09 [debug] 23093#0: *1 mail proxy imap auth handler
2010/07/14 09:25:09 [debug] 23093#0: *1 recv: fd:8 23 of 4096
2010/07/14 09:25:09 [error] 23093#0: *1 upstream sent invalid response: 
"a001 NO Login failed." while reading response from upstream, client: 
10.2.5.60, server: 0.0.0.0:143, login: "trashcan", upstream: 10.0.7.134:143
2010/07/14 09:25:09 [debug] 23093#0: *1 close mail proxy connection: 8
2010/07/14 09:25:09 [debug] 23093#0: *1 event timer del: 8: 1279117569461
2010/07/14 09:25:09 [debug] 23093#0: *1 send: fd:3 29 of 29
2010/07/14 09:25:09 [debug] 23093#0: *1 close mail connection: 3
2010/07/14 09:25:09 [debug] 23093#0: *1 free: 0000000006A14DE0
2010/07/14 09:25:09 [debug] 23093#0: *1 free: 0000000006A13CC0
2010/07/14 09:25:09 [debug] 23093#0: *1 free: 0000000006A0DD90
2010/07/14 09:25:09 [debug] 23093#0: *1 free: 0000000006A0DB40, unused: 0
2010/07/14 09:25:09 [debug] 23093#0: *1 free: 0000000006A13BB0, unused: 16
2010/07/14 09:25:09 [debug] 23093#0: *1 free: 0000000006A14CD0, unused: 13
2010/07/14 09:25:09 [debug] 23093#0: timer delta: 1
2010/07/14 09:25:09 [debug] 23093#0: posted events 0000000000000000
2010/07/14 09:25:09 [debug] 23093#0: worker cycle
2010/07/14 09:25:09 [debug] 23093#0: epoll timer: -1

telnet session:
* OK IMAP4 ready
a001 login trashcan ******
* BAD internal server error
Connection closed by foreign host.

If i were to telnet to imap server (10.0.7.134:143) directly it does 
work. I feel like I'm missing something simple, or maybe just not 
understanding how nginx works. What am I missing?

More information about the nginx mailing list