Problems with imap proxy sending invalid username

Server NGINX
1

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?

2

Hello!

On Wed, Jul 14, 2010 at 09:28:50AM -0500, Pat wrote:

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.

[…]

2010/07/14 09:03:42 [debug] 22837#0: *4 ngx_imap_start: line.data:
a001 LOGIN {8}
�0R

This isn’t what nginx normally logs, looks like you added this
logging yourself, right? You did it wrong - this string contains
only 16 bytes (“a001 LOGIN {8}” CRLF).

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

Here we see that your backend replied “NO Login failed.” right
after it got initial “a001 LOGIN {8}” CRLF string. Expected reply
is command continuation request.

Looks like your backend just doesn’t support IMAP4rev1, at least
not string literals. See RFC 3501 for details.

Maxim D.

3

On 7/14/2010 10:07 AM, Maxim D. wrote:

This isn’t what nginx normally logs, looks like you added this
logging yourself, right? You did it wrong - this string contains
only 16 bytes (“a001 LOGIN {8}” CRLF).

Yes it is. Sorry, I didn’t look around too much just used a debug
function in the same file. I was just trying to confirm if my tcpdump
output was correct. No other modifications were made besides some calls
to that same function.

Here we see that your backend replied “NO Login failed.” right
after it got initial “a001 LOGIN {8}” CRLF string. Expected reply
is command continuation request.

Looks like your backend just doesn’t support IMAP4rev1, at least
not string literals. See RFC 3501 for details.

Maxim D.

Oh OK, I didn’t recognize that it was a command continuation request, I
thought it was perhaps some kind of error in how I compiled nginx, and
it was not escaping its strings correctly. Unfortunately my auth backend
does not support this, is there any way I can send the login
immediately? After the login it will be a real imap server responding
which could handle command continuation requests for regular IMAP
commands (just not at LOGIN). At this particular stage it normally only
does either a cookie based login or a regular LOGIN username password.
Thank you for the fast response.