# Problems with imap proxy sending invalid username

**URL:** <https://www.ruby-forum.com/t/problems-with-imap-proxy-sending-invalid-username/191570>\
**Category:** NGINX\
**Created:** [July 14, 2010, 4:30pm UTC](https://www.ruby-forum.com/t/problems-with-imap-proxy-sending-invalid-username/191570 "2010-07-14T16:30:21Z")\
**Posts on this page:** 3\
**Page:** 1

<div class="post-metadata">

**Author:** ![pat](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/p/8491ac/32.png) [@pat](https://www.ruby-forum.com/u/pat)\
**Post date:** [July 14, 2010, 4:30pm UTC](https://www.ruby-forum.com/t/problems-with-imap-proxy-sending-invalid-username/191570/1 "2010-07-14T16:30:21Z")

</div>

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?

---

<div class="post-metadata">

**Author:** ![pat](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/p/8491ac/32.png) [@pat](https://www.ruby-forum.com/u/pat)\
**Post date:** [July 14, 2010, 5:07pm UTC](https://www.ruby-forum.com/t/problems-with-imap-proxy-sending-invalid-username/191570/2 "2010-07-14T17:07:49Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![pat](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/p/8491ac/32.png) [@pat](https://www.ruby-forum.com/u/pat)\
**Post date:** [July 14, 2010, 5:21pm UTC](https://www.ruby-forum.com/t/problems-with-imap-proxy-sending-invalid-username/191570/3 "2010-07-14T17:21:17Z")

</div>

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.