Plesk 11.5.30 bug - courier-imap module "authpsa"

[nethubonline]

Users has upload their own horde to their own subscription hosting space, there is no problem on Plesk 11.0.9 .

However upgraded to Plesk 11.5.30, while user enter wrong password to Horde, it shows error :

Fatal error: Call to a member function write() on a non-object in /var/www/vhosts/plesktest3.test.net/httpdocs/psa-pear/pear/php/Horde/Imap/Client/Socket.php on line 3912

Initially we thought this problem is on horde, however after checking with horde's developer Jan, confirm that it is not the problem on horde, but it is about the courier-imap module "authpsa" problem that is provided by Plesk auth module.

http://thread.gmane.org/gmane.comp.horde.user/32161/focus=32167

Below are the logs about the courier-imapd debug log, it seems that authpsa or auth_psa_common return wrong output which cause the courier-imapd "Input/output error"


Jul 15 19:21:04 plesktest2 courier-imapd: Connection, ip=[::1]
Jul 15 19:21:04 plesktest2 courier-authdaemon: received auth request, service=imap, authtype=cram-md5
Jul 15 19:21:04 plesktest2 courier-authdaemon: authpsa: trying this module
Jul 15 19:21:04 plesktest2 courier-authdaemon: cram: challenge=PDYyREJCNDcwQUNFNDYyM0VDMDY3QTkxNjhEQkY0MUY0QHBsZXNrdGVzdDIuZGVtbzM2MC5uZXQ+, response=dGVzdEBwbGVza3Rlc3QzLmRlbW8zNjAubmV0IGRjZDVlYjdjZDMyZjhiNWYxMDdlNWI0ZTMzNmRkYjY2
Jul 15 19:21:04 plesktest2 courier-authdaemon: cram: decoded challenge/response, username '[email protected]'
Jul 15 19:21:04 plesktest2 courier-authdaemon: authpsa: sysusername=popuser, sysuserid=30, sysgroupid=31, homedir=/var/qmail/mailnames/plesktest3.test.net/test, [email protected], fullname=<null>, maildir=<null>, quota=<null>, options=<null>
Jul 15 19:21:04 plesktest2 courier-authdaemon: cram validation failed
Jul 15 19:21:04 plesktest2 courier-authdaemon: authpsa: auth_psa_common() callback returned -1
Jul 15 19:21:04 plesktest2 courier-authdaemon: authpsa: REJECT - try next module
Jul 15 19:21:04 plesktest2 courier-authdaemon: FAIL, all modules rejected
Jul 15 19:21:04 plesktest2 courier-imapd: LOGIN FAILED, method=CRAM-MD5, ip=[::1]
Jul 15 19:21:09 plesktest2 courier-authdaemon: received auth request, service=imap, authtype=login
Jul 15 19:21:09 plesktest2 courier-authdaemon: authpsa: trying this module
Jul 15 19:21:09 plesktest2 courier-authdaemon: authpsa: password for account '[email protected]' is wrong
Jul 15 19:21:09 plesktest2 courier-authdaemon: authpsa: sysusername=popuser, sysuserid=30, sysgroupid=31, homedir=<null>, address=<null>, fullname=<null>, maildir=<null>, quota=<null>, options=<null>
Jul 15 19:21:09 plesktest2 courier-authdaemon: authpsa: TEMPFAIL - no more modules will be tried
Jul 15 19:21:09 plesktest2 courier-imapd: LOGIN FAILED, method=PLAIN, ip=[::1]
Jul 15 19:21:09 plesktest2 courier-imapd: authentication error: Input/output error


I checked Plesk 11.0 is using psa-courier-imap-3.0.8 while Plesk 11.5 is using psa-courier-imap-4.12.0 & psa-courier-authlib-0.65.0, obviously the auth module "authpsa" is new or not working well in Plesk 11.5

Can anyone confirm this problem and has solution?

 

[Nikolay.]

Would be nice if you turned debug logging all the way up (DEBUG_LOGIN=2 in /etc/courier-imap/authlib/authdaemonrc).

Also it's more likely that you have problems with authentication DB than with authpsa module. At least authpsa thinks your password is wrong, but there is a matching account in DB. Check whether expected credentials are in output of # plesk sbin mail_auth_view

If not - run mail_restore / mchk

 

[nethubonline]

Thanks Nikolay,

After turned on DEBUG_LOGIN=2 , I got log below

Jul 16 11:23:04 plesktest2 courier-imapd: Connection, ip=[::1]
Jul 16 11:23:04 plesktest2 courier-authdaemon: received auth request, service=imap, authtype=cram-md5
Jul 16 11:23:04 plesktest2 courier-authdaemon: authpsa: trying this module
Jul 16 11:23:04 plesktest2 courier-authdaemon: authpsa: authentication request with service='imap' authtype='cram-md5' authdata='PEQ1NUE0NjA2RkUxRDREQ0U2MTgxQjM0OTZBRjQxNTdEQHBsZXNrdGVzdDIuZGVtbzM2MC5uZXQ+.dGVzdEBwbGVza3Rlc3QzLmRlbW8zNjAubmV0IDEzOGIzZmNiMTljMzNlYmU0MmZhNzhmMTc2MmQ3NTk5.'
Jul 16 11:23:04 plesktest2 courier-authdaemon: cram: challenge=PEQ1NUE0NjA2RkUxRDREQ0U2MTgxQjM0OTZBRjQxNTdEQHBsZXNrdGVzdDIuZGVtbzM2MC5uZXQ+, response=dGVzdEBwbGVza3Rlc3QzLmRlbW8zNjAubmV0IDEzOGIzZmNiMTljMzNlYmU0MmZhNzhmMTc2MmQ3NTk5
Jul 16 11:23:04 plesktest2 courier-authdaemon: cram: decoded challenge/response, username '[email protected]'
Jul 16 11:23:04 plesktest2 courier-authdaemon: authpsa: decoded cram user='[email protected]' challenge='<[email protected]>' response='138b3fcb19c33ebe42fa78f1762d7599'
Jul 16 11:23:04 plesktest2 courier-authdaemon: authpsa: auth_psa_common(user='[email protected]', pass='(null)')
Jul 16 11:23:04 plesktest2 courier-authdaemon: authpsa: password for '[email protected]' is plain 'Passtest'
Jul 16 11:23:04 plesktest2 courier-authdaemon: authpsa: sysusername=popuser, sysuserid=30, sysgroupid=31, homedir=/var/qmail/mailnames/plesktest3.test.net/test, [email protected], fullname=<null>, maildir=<null>, quota=<null>, options=<null>
Jul 16 11:23:04 plesktest2 courier-authdaemon: authpsa: clearpasswd=Passtest, passwd=<null>
Jul 16 11:23:04 plesktest2 courier-authdaemon: cram validation failed
Jul 16 11:23:04 plesktest2 courier-authdaemon: authpsa: auth_psa_common() callback returned -1
Jul 16 11:23:04 plesktest2 courier-authdaemon: authpsa: REJECT - try next module
Jul 16 11:23:04 plesktest2 courier-authdaemon: FAIL, all modules rejected
Jul 16 11:23:04 plesktest2 courier-imapd: LOGIN FAILED, method=CRAM-MD5, ip=[::1]
Jul 16 11:23:09 plesktest2 courier-authdaemon: received auth request, service=imap, authtype=login
Jul 16 11:23:09 plesktest2 courier-authdaemon: authpsa: trying this module
Jul 16 11:23:09 plesktest2 courier-authdaemon: authpsa: authentication request with service='imap' authtype='login' authdata='[email protected].'
Jul 16 11:23:09 plesktest2 courier-authdaemon: authpsa: auth_psa_common(user='[email protected]', pass='PasstestPasstest')
Jul 16 11:23:09 plesktest2 courier-authdaemon: authpsa: password for '[email protected]' is plain 'Passtest'
Jul 16 11:23:09 plesktest2 courier-authdaemon: authpsa: password for account '[email protected]' is wrong
Jul 16 11:23:09 plesktest2 courier-authdaemon: authpsa: sysusername=popuser, sysuserid=30, sysgroupid=31, homedir=<null>, address=<null>, fullname=<null>, maildir=<null>, quota=<null>, options=<null>
Jul 16 11:23:09 plesktest2 courier-authdaemon: authpsa: clearpasswd=<null>, passwd=<null>
Jul 16 11:23:09 plesktest2 courier-authdaemon: authpsa: TEMPFAIL - no more modules will be tried
Jul 16 11:23:09 plesktest2 courier-imapd: LOGIN FAILED, method=PLAIN, ip=[::1]
Jul 16 11:23:09 plesktest2 courier-imapd: authentication error: Input/output error


Output of /usr/local/psa/admin/sbin/mail_auth_view:

# /usr/local/psa/admin/sbin/mail_auth_view
Authentication database contents:
+--------------------------------------+-----+--------------------------------------+
| address |flags| password |
+--------------------------------------+-----+--------------------------------------+
| [email protected] | | Passtest |
+--------------------------------------+-----+--------------------------------------+
Flags
A - account disabled
D - domain disabled
E - password encrypted

Tried mail_restore / mchk but doesn't help. I just tried to install a new Plesk 11.5.30 on fresh CentOS 6.2, and installed a complete new Horde so that there should be no authentication DB problem, and the final result is same that gettingCall to a member function write() on a non-object

I am not experienced on IMAP debugging, do you get any hints from above debug log?

 

[Nikolay.]

Tried mail_restore / mchk but doesn't help. I just tried to install a new Plesk 11.5.30 on fresh CentOS 6.2, and installed a complete new Horde so that there should be no authentication DB problem, and the final result is same that gettingCall to a member function write() on a non-object

I am not experienced on IMAP debugging, do you get any hints from above debug log?

Yes, mail_restore / mchk will not help since there is not problem with mail authentication DB (as far as I can see). Plesk 11.5.30 should be installed on CentOS 6.4 to avoid potential problems (you should at least have repositories pointing to latest CentOS, which you probably do). The fact that you get errors on clean installation is extremely weird.

Debug log you posted suggests that supplied password in fact does not match actual password 'Passtest'.

 

[nethubonline]

Dear Nikolay,

Thank you for your help.

Sorry for the password, actually I modified the password in the log so that made you confuse.


I just installed a fresh Plesk 11.5.30 CentOS 6 115130711.13 on CentOS release 6.4 (Final), and most updated Horde, the problem still persists.

Below are all the debug log that I did not make any modification on it. (Real password is "correctpass", and I entered wrong password as "wrongpass")


Jul 16 14:54:36 plesktest3 courier-imapd: Connection, ip=[::1]
Jul 16 14:54:36 plesktest3 courier-authdaemon: received auth request, service=imap, authtype=cram-md5
Jul 16 14:54:36 plesktest3 courier-authdaemon: authpsa: trying this module
Jul 16 14:54:36 plesktest3 courier-authdaemon: authpsa: authentication request with service='imap' authtype='cram-md5' authdata='PDQ4QjQzQTg5RDNEMEUyQTc4QjNEQkNDNTA0QTEyNURGQHBsZXNrdGVzdDMuZGVtbzM2MC5uZXQ+.dGVzdEBwbGVza3Rlc3QzLnRlc3QubmV0IDEyYWE5YmE1ZDI1ODczYzEwNWZhYTUyODAwOGY0MDg4.'
Jul 16 14:54:36 plesktest3 courier-authdaemon: cram: challenge=PDQ4QjQzQTg5RDNEMEUyQTc4QjNEQkNDNTA0QTEyNURGQHBsZXNrdGVzdDMuZGVtbzM2MC5uZXQ+, response=dGVzdEBwbGVza3Rlc3QzLnRlc3QubmV0IDEyYWE5YmE1ZDI1ODczYzEwNWZhYTUyODAwOGY0MDg4
Jul 16 14:54:36 plesktest3 courier-authdaemon: cram: decoded challenge/response, username '[email protected]'
Jul 16 14:54:36 plesktest3 courier-authdaemon: authpsa: decoded cram user='[email protected]' challenge='<[email protected]>' response='12aa9ba5d25873c105faa528008f4088'
Jul 16 14:54:36 plesktest3 courier-authdaemon: authpsa: auth_psa_common(user='[email protected]', pass='(null)')
Jul 16 14:54:36 plesktest3 courier-authdaemon: authpsa: password for '[email protected]' is plain 'correctpass'
Jul 16 14:54:36 plesktest3 courier-authdaemon: authpsa: sysusername=popuser, sysuserid=30, sysgroupid=31, homedir=/var/qmail/mailnames/plesktest3.test.net/test, [email protected], fullname=<null>, maildir=<null>, quota=<null>, options=<null>
Jul 16 14:54:36 plesktest3 courier-authdaemon: authpsa: clearpasswd=correctpass, passwd=<null>
Jul 16 14:54:36 plesktest3 courier-authdaemon: cram validation failed
Jul 16 14:54:36 plesktest3 courier-authdaemon: authpsa: auth_psa_common() callback returned -1
Jul 16 14:54:36 plesktest3 courier-authdaemon: authpsa: REJECT - try next module
Jul 16 14:54:36 plesktest3 courier-authdaemon: FAIL, all modules rejected
Jul 16 14:54:36 plesktest3 courier-imapd: LOGIN FAILED, method=CRAM-MD5, ip=[::1]
Jul 16 14:54:41 plesktest3 courier-authdaemon: received auth request, service=imap, authtype=login
Jul 16 14:54:41 plesktest3 courier-authdaemon: authpsa: trying this module
Jul 16 14:54:41 plesktest3 courier-authdaemon: authpsa: authentication request with service='imap' authtype='login' authdata='[email protected].'
Jul 16 14:54:41 plesktest3 courier-authdaemon: authpsa: auth_psa_common(user='[email protected]', pass='wrongpass')
Jul 16 14:54:41 plesktest3 courier-authdaemon: authpsa: password for '[email protected]' is plain 'correctpass'
Jul 16 14:54:41 plesktest3 courier-authdaemon: authpsa: password for account '[email protected]' is wrong
Jul 16 14:54:41 plesktest3 courier-authdaemon: authpsa: sysusername=popuser, sysuserid=30, sysgroupid=31, homedir=<null>, address=<null>, fullname=<null>, maildir=<null>, quota=<null>, options=<null>
Jul 16 14:54:41 plesktest3 courier-authdaemon: authpsa: clearpasswd=<null>, passwd=<null>
Jul 16 14:54:41 plesktest3 courier-authdaemon: authpsa: TEMPFAIL - no more modules will be tried
Jul 16 14:54:41 plesktest3 courier-imapd: LOGIN FAILED, method=PLAIN, ip=[::1]
Jul 16 14:54:41 plesktest3 courier-imapd: authentication error: Input/output error

 

[Nikolay.]

Um... let me get this clear: you attempt to login with invalid password and complain that Courier-Authlib/authpsa doesn't let you in?! What behavior do you expect?

 

[nethubonline]

Hi Nikolay,

Ok, let me explain.

While I login with CORRECT password, there is no problem.

While I login with WRONG password, horde should report "Login failed because your username or password was entered incorrectly.", however now I got PHP error "[Tue Jul 16 15:26:28 2013] [warn] [client 1.2.3.4] mod_fcgid: stderr: PHP Fatal error: Call to a member function write() on a non-object in /usr/share/psa-pear/pear/php/Horde/Imap/Client/Socket.php on line 3912, referer: http://webmail.plesktest3.test.net/login.php?new_lang=en_US"

After reporting to http://thread.gmane.org/gmane.comp.horde.user/32161/focus=32167, horde's developer confirmed it is relating to IMAP server problem, hence I go to see IMAP log and I found "authentication error: Input/output error", I believe it is not normal password failure error but the auth problem on authpsa .

Maybe I can do one more test on another non Plesk server and install the courier imap and the horde, then I can confirm whether it is horde, courier IMAP, or authpsa problem.

Hope it would be more clear now.

 

[Nikolay.]

You don't need to test on another Plesk server - you'll get the same results. AFAIK, "authentication error: Input/output error" is just a way this version of Courier-IMAP reacts to authentication errors. There is nothing wrong there (you can check it with any mail client or just telnet). I need to replicate the issue, but from the looks of it it is Horde problem.

 

[Nikolay.]

I just tested it and both Horde and Roundcube webmails bundled with Plesk 11.5.30 work fine (no PHP errors are shown in case of invalid password, but only a nice error message). I'm sure it's a bug in the custom version of Horde you're using. I suggest switching to the one bundled with Plesk.

 

[nethubonline]

Hi Nikolay,

Thanks for your help. May I know which horde version you are testing? Is that one bundled with Plesk 11.5.30?

 

[Nikolay.]

I just tested it and both Horde and Roundcube webmails bundled with Plesk 11.5.30 work fine

May I know which horde version you are testing? Is that one bundled with Plesk 11.5.30?

Yes, it is.

 

[nethubonline]

Hi Nikolay,

Yeah, I confirmed that horde version does not generate any problem / error, however seems the new horde version check the IMAP more deeply.

What I am testing is the new version (Horde Version: 5.1.1, Imp [Mail]: H5 (6.1.2)), and I am sure I installed this new horde correctly (under hosting space, not overwritten the original one bundled with Plesk).

As I said before, I guessed this problem is on Horde too, but after confirmation with horde official developer, the problem is on backend, which means at the IMAP side.


Hence I spend several hours to install a new courier-imap (4.13), courier-authlib (0.65), and new horde (Horde Version: 5.1.1, Imp [Mail]: H5 (6.1.2)), but I don't use authpsa because I am not using Plesk for this testing, instead of authpsa I use authuserdb and other auth module, I confirmed there is no any problem for it now. From this testing, I am quite sure the problem is either on Plesk authpsa or the courier-authlib (psa-courier-authlib-0.65.0-cos6.build115130711.13.x86_64) .

To prove it, you just need to install a new horde on any vhosts space (/var/www/vhosts/xxxx.com) for testing.

(Yep, you may say other version of horde was not tested by Parallels yet so may cause unexpected problem, but I hope you understand that the error of courier "authentication error: Input/output error" is still not expected. this error exists even I use the original horde (bundled with Plesk). Hence I think this problem is either under authpsa or courier-authlib, and solving it can let Parallels upgrade horde in the future.)

 

[nethubonline]

Hi Nikolay,

For more reference, below is the log (DEBUG_LOGIN=2) that I tested for "new courier-imap (4.13), courier-authlib (0.65), and new horde (Horde Version: 5.1.1, Imp [Mail]: H5 (6.1.2)), but I don't use authpsa because I am not using Plesk for this testing", you can see there will be no "authentication error: Input/output error" even I entered wrong password.




While I entered wrong password:

Jul 17 11:21:14 plesktest4 imapd: Connection, ip=[::1]
Jul 17 11:21:14 plesktest4 authdaemond: received auth request, service=imap, authtype=login
Jul 17 11:21:14 plesktest4 authdaemond: authshadow: trying this module
Jul 17 11:21:14 plesktest4 authdaemond: authshadow: sysusername=test, sysuserid=<null>, sysgroupid=507, homedir=/home/test, address=test, fullname=, maildir=<null>, quota=<null>, options=<null>
Jul 17 11:21:14 plesktest4 authdaemond: authshadow: clearpasswd=<null>, passwd=x
Jul 17 11:21:14 plesktest4 authdaemond: supplied password 'wrongpass' does not match encrypted password '$6$p1L5jhCW$sdIHaaKD728ORDjcqrIrgxXA8Ot5TJhUu73t241Ludu2LXiNRC3CSEGVTAwiBJ2k7ZBwxN06hZgHAXV2GI2Aq1'
Jul 17 11:21:14 plesktest4 authdaemond: authshadow: REJECT - try next module
Jul 17 11:21:14 plesktest4 authdaemond: FAIL, all modules rejected
Jul 17 11:21:14 plesktest4 imapd: LOGIN FAILED, user=test, ip=[::1]
Jul 17 11:21:19 plesktest4 imapd: Disconnected, ip=[::1], time=5



While I entered correct password:

Jul 17 11:20:52 plesktest4 imapd: Connection, ip=[::1]
Jul 17 11:20:52 plesktest4 authdaemond: received auth request, service=imap, authtype=login
Jul 17 11:20:52 plesktest4 authdaemond: authshadow: trying this module
Jul 17 11:20:52 plesktest4 authdaemond: authshadow: sysusername=test, sysuserid=<null>, sysgroupid=507, homedir=/home/test, address=test, fullname=, maildir=<null>, quota=<null>, options=<null>
Jul 17 11:20:52 plesktest4 authdaemond: authshadow: clearpasswd=<null>, passwd=x
Jul 17 11:20:52 plesktest4 authdaemond: password matches successfully
Jul 17 11:20:52 plesktest4 authdaemond: Authenticated: sysusername=test, sysuserid=<null>, sysgroupid=507, homedir=/home/test, address=test, fullname=, maildir=<null>, quota=<null>, options=<null>
Jul 17 11:20:52 plesktest4 authdaemond: Authenticated: clearpasswd=correctpass, passwd=$6$p1L5jhCW$sdIHaaKD728ORDjcqrIrgxXA8Ot5TJhUu73t241Ludu2LXiNRC3CSEGVTAwiBJ2k7ZBwxN06hZgHAXV2GI2Aq1
Jul 17 11:20:52 plesktest4 imapd: LOGIN, user=test, ip=[::1], port=[56991], protocol=IMAP
Jul 17 11:20:52 plesktest4 imapd: LOGOUT, user=test, ip=[::1], headers=0, body=0, rcvd=24, sent=229, time=0
Jul 17 11:20:53 plesktest4 imapd: Connection, ip=[::1]
Jul 17 11:20:53 plesktest4 authdaemond: received auth request, service=imap, authtype=login
Jul 17 11:20:53 plesktest4 authdaemond: authshadow: trying this module
Jul 17 11:20:53 plesktest4 authdaemond: authshadow: sysusername=test, sysuserid=<null>, sysgroupid=507, homedir=/home/test, address=test, fullname=, maildir=<null>, quota=<null>, options=<null>
Jul 17 11:20:53 plesktest4 authdaemond: authshadow: clearpasswd=<null>, passwd=x
Jul 17 11:20:53 plesktest4 authdaemond: password matches successfully
Jul 17 11:20:53 plesktest4 authdaemond: Authenticated: sysusername=test, sysuserid=<null>, sysgroupid=507, homedir=/home/test, address=test, fullname=, maildir=<null>, quota=<null>, options=<null>
Jul 17 11:20:53 plesktest4 authdaemond: Authenticated: clearpasswd=correctpass, passwd=$6$p1L5jhCW$sdIHaaKD728ORDjcqrIrgxXA8Ot5TJhUu73t241Ludu2LXiNRC3CSEGVTAwiBJ2k7ZBwxN06hZgHAXV2GI2Aq1
Jul 17 11:20:53 plesktest4 imapd: LOGIN, user=test, ip=[::1], port=[56992], protocol=IMAP
Jul 17 11:20:53 plesktest4 imapd: /usr/lib/courier-imap/etc/shared/index: No such file or directory
Jul 17 11:20:53 plesktest4 imapd: LOGOUT, user=test, ip=[::1], headers=0, body=0, rcvd=161, sent=626, time=0
Jul 17 11:20:54 plesktest4 imapd: Connection, ip=[::1]
Jul 17 11:20:54 plesktest4 authdaemond: received auth request, service=imap, authtype=login
Jul 17 11:20:54 plesktest4 authdaemond: authshadow: trying this module
Jul 17 11:20:54 plesktest4 authdaemond: authshadow: sysusername=test, sysuserid=<null>, sysgroupid=507, homedir=/home/test, address=test, fullname=, maildir=<null>, quota=<null>, options=<null>
Jul 17 11:20:54 plesktest4 authdaemond: authshadow: clearpasswd=<null>, passwd=x
Jul 17 11:20:54 plesktest4 authdaemond: password matches successfully
Jul 17 11:20:54 plesktest4 authdaemond: Authenticated: sysusername=test, sysuserid=<null>, sysgroupid=507, homedir=/home/test, address=test, fullname=, maildir=<null>, quota=<null>, options=<null>
Jul 17 11:20:54 plesktest4 authdaemond: Authenticated: clearpasswd=correctpass, passwd=$6$p1L5jhCW$sdIHaaKD728ORDjcqrIrgxXA8Ot5TJhUu73t241Ludu2LXiNRC3CSEGVTAwiBJ2k7ZBwxN06hZgHAXV2GI2Aq1
Jul 17 11:20:54 plesktest4 imapd: LOGIN, user=test, ip=[::1], port=[56994], protocol=IMAP
Jul 17 11:20:54 plesktest4 imapd: LOGOUT, user=test, ip=[::1], headers=0, body=0, rcvd=170, sent=638, time=0

 

[Nikolay.]

OK, thank you very much for your investigation!

However I still think there is a bug in Horde/Imp since any quality software should not fail in this way - showing internal interpreter error to user.

 

[nethubonline]

Nikolay,


hahaahaaaaaaaaaaaaaaa, yep, you are right, I think it should not show the internal interpreter error to user in the front end (laughing.................)

Anyway, I will submit this to horde, maybe they can show a friendly error instead of PHP error, whatever......

However, if possible would you check the IMAP or authpsa for that error too?

 

[Nikolay.]

Regarding Courier-IMAP/Authlib: looks like there is either design or documentation flaw.

www.courier-mta.org/authlib/README_authlib.html says that:

The authentication function should return a negative value if the login ID is invalid. The authentication library will try the next authentication module.

The authentication function should return a positive value if the login ID is valid, but the password is invalid. The authentication library will not try any more authentication modules.

Which authpsa actually conforms to by returning 1 in case of password mismatch (when using authtype=login).

If you look into auth_login(3) or similar page you'll see:

By convention, a positive return value indicates an internal, temporary failure, such as the authentication daemon process not running; a negative return value indicates that this request was processed, but it failed.

Which clearly contradicts the information above. Also _authdaemondo() from Courier-Authlib suggests that return code would stay 1 in this case.

 

[nethubonline]

Hi Nikolay,

I am not sure what is wrong with courier authlib, however the debug log shows "authpsa: auth_psa_common() callback returned -1", is it correct?


Anyway, I just do one more test which can confirm something more.


Environment:
Plesk 11.5.30
psa-courier-imap-4.12.0-cos6.build115130710.20.x86_64
psa-courier-authlib-0.65.0-cos6.build115130711.13.x86_64
Horde Version: 5.1.1, Imp [Mail]: H5 (6.1.2) (yep, new installed with most updated version)


Step 1. modify /etc/courier-imap/authlib/authdaemonrc from:

authmodulelist="authpsa "

to

authmodulelist="authshadow "



Step 2. download file http://vo.demo360.net/libauthshadow.tar.gz (This library was copied from another courier-authlib server, please do not care if it works or not, worst case is just error, ) and extract it to /usr/lib64/courier-authlib , just like this:

-rw-r--r-- 1 root root 5552 Jul 17 13:13 /usr/lib64/courier-authlib/libauthshadow.a
-rwxr-xr-x 1 root root 1075 Jul 17 13:13 /usr/lib64/courier-authlib/libauthshadow.la
-rwxr-xr-x 1 root root 6832 Jul 17 13:13 /usr/lib64/courier-authlib/libauthshadow.so
lrwxrwxrwx 1 root root 16 Jul 17 18:28 /usr/lib64/courier-authlib/libauthshadow.so.0 -> libauthshadow.so


Step 3. restart courier-auth by "/etc/rc.d/init.d/courier-authdaemon restart"

Step 4. add a user by "useradd testtest" and give it a password by "passwd testtest"

Step 5. Create Maildir accordingly, just like this:

/home/testtest/Maildir/cur
/home/testtest/Maildir/new
/home/testtest/Maildir/tmp

Step 6. Now you should be able to login the horde with user "testtest", you can see even you enter wrong password, there is friendly failure message instead of PHP error.


From above situation, you can see in the same environment version of Plesk, courier-imap, courier-authlib, Horde, if you use authshadow as auth module, there is no problem.
However there will be PHP error and the IMAP debug log would show some strange error like this: "authpsa: auth_psa_common() callback returned -1" , "authentication error: Input/output error"


Below is the IMAP debug log while using authshadow
Jul 17 15:09:25 plesktest3 courier-imapd: Connection, ip=[::1]
Jul 17 15:09:25 plesktest3 courier-authdaemon: received auth request, service=imap, authtype=login
Jul 17 15:09:25 plesktest3 courier-authdaemon: authshadow: trying this module
Jul 17 15:09:25 plesktest3 courier-authdaemon: authshadow: REJECT - try next module
Jul 17 15:09:25 plesktest3 courier-authdaemon: FAIL, all modules rejected
Jul 17 15:09:25 plesktest3 courier-imapd: LOGIN FAILED, user=test, ip=[::1]
Jul 17 15:09:30 plesktest3 courier-authdaemon: received auth request, service=imap, authtype=login
Jul 17 15:09:30 plesktest3 courier-authdaemon: authshadow: trying this module
Jul 17 15:09:30 plesktest3 courier-authdaemon: authshadow: REJECT - try next module
Jul 17 15:09:30 plesktest3 courier-authdaemon: FAIL, all modules rejected
Jul 17 15:09:30 plesktest3 courier-imapd: LOGIN FAILED, method=PLAIN, ip=[::1]
Jul 17 15:09:35 plesktest3 courier-authdaemon: received auth request, service=imap, authtype=cram-md5
Jul 17 15:09:35 plesktest3 courier-authdaemon: authshadow: trying this module
Jul 17 15:09:35 plesktest3 courier-authdaemon: authshadow: REJECT - try next module
Jul 17 15:09:35 plesktest3 courier-authdaemon: FAIL, all modules rejected
Jul 17 15:09:35 plesktest3 courier-imapd: LOGIN FAILED, method=CRAM-MD5, ip=[::1]
Jul 17 15:09:40 plesktest3 courier-imapd: Disconnected, ip=[::1], time=15, starttls=1


Hope it is more clear now, we would be appreciate and very happy if this problem can be solved




Besides, I tried to attach file in this forum, but in the pop up page it is blank, I tried firefox 21 and IE 10 but still blank.

 

[Nikolay.]

the debug log shows "authpsa: auth_psa_common() callback returned -1", is it correct?

This is not relevant, since it refers to cram callback. But Horde complains after plain authentication attempt.

The log you provided just confirms that authshadow doesn't follow Courier-Authlib guidelines for return codes. There should be no "try next module" if login matches, but password does not.

Anyhow, it might be useful for authpsa to "play along" with other modules, but it's definitely not correct.

 

[nethubonline]

Understood, hope this can help to "play along" with other module and courier auth and we look forward to hearing new patch soon

 

[nethubonline]

Hi Nikolay and other Parallels developer,

I just tested Plesk 11.5.30 MU7, seems the problem still exists, I think you are hard working on this.

I have some updates for this issue, don't know if it can help you to fix the problem in MU8


1. courier provides "authtest" for testing the module, so we can by pass the horde or HTTP (ref: http://www.courier-mta.org/authlib/authtest.html)

while using authshadow, the output is normal as expected
# authtest [email protected] 123456
Authentication FAILED: Operation not permitted


while using authpsa, the output is "Input/output error"
# authtest [email protected] 123456
Authentication FAILED: Input/output error



2. Not sure if it is relevant, according to the debug logs in previous posts, "authpsa: TEMPFAIL" may be the hints, because while using "authshadow" there is no "TEMPFAIL", but only "authshadow: REJECT".

And according to http://www.courier-mta.org/authlib/README.authdebug.html ,

ACCEPT
The user was authenticated successfully
REJECT
The module did not know this username, or the user gave invalid credentials. The request is passed to the next module.
TEMPFAIL
The module suffered an internal failure, such as inability to contact an external database. The login is rejected, and no further modules are tried.

It tells us that the module suffered an internal failure.



3. Just got report from users who are using Outlook Express / iphone

while using authshadow, it can show "Login failed" correctly

Your 'Inbox' folder was not polled for its unread count. The operation was canceled by the user. Account: 'plesktest3.test.net', Server: 'plesktest3.test.net', Protocol: IMAP, Server Response: 'Login failed.', Port: 143, Secure(SSL): No, Error Number: 0x800C006F

while using authpsa, it shows "Temporary problem, please try again later". Since it is not login failure, users will report to server admin that the IMAP server got problem.

Your 'Inbox' folder was not polled for its unread count. Your IMAP server has closed the connection. This may occur if you have left the connection idle for too long. Account: 'plesktest3.test.net', Server: 'plesktest3.test.net', Protocol: IMAP, Server Response: 'Temporary problem, please try again later', Port: 143, Secure(SSL): No, Error Number: 0x800CCCDD

Now the problem not only occurs in horde, but also normal IMAP software, hence I hope the problem can be fixed ASAP.