Error from admin GUI

[TomL]

When I click on any user in the admin GUI other than the oxadmin user, I get the following:

Error code: Error occured in: com.openexchange.admin.rmi.extensions.OXUserMailfilterExtension! Errortext: com.openexchange.admin.rmi.exceptions.OXSieveHandlerInvalidCredentialsException: Authentication failed (SVL-0001,465066230-55)

and everything's disabled: can't change anything. Not sure what to check here... everything else works. Sieve is working:

root@elise:/etc# telnet localhost 2000
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
"IMPLEMENTATION" "Cyrus timsieved v2.2.13"
"SASL" "LOGIN PLAIN"
"SIEVE" "fileinto reject envelope vacation imapflags notify subaddress relational comparator-i;ascii-numeric regex"
"STARTTLS"
OK

I can send mail, receive mail as multiple users, can't seem to break anything else.

[Martin Heiland]

Hi,

did you sniff the traffic on port 2000 when accessing the user configuration? I guess wrong credentials are used caused by a missing "admin: oxadmin" entry at the cyrus configuration.

Greetings

[TomL]

packet capture

I have "admins: oxadmin" in /etc/imapd.conf, so that's not it. I can log in to the IMAP server as oxadmin.

Here's a wireshark/libpcap packet capture of port 2000 traffic when I click on a user in the admin gui.

It seems there is something else -- I can't view mail as "oxadmin", I get

Error code: No IMAP Account exists for user Open-Xchange Administrator(2) in context 1 (MSG-0096, 465066230-78)

Apparently I need to create an account in Cyrus for oxadmin... I'll see if I can find any documentation on that. It's not included in the install doc on the wiki that I can see.

[Gertjan]

Are you sure /etc/pam.d/sieve looks the same as /etc/pam.d/imap?

[TomL]

Yep.

They weren't but they are identical now, but still the same problem (new packet capture still looks the same).

I've got cyradm working but it doesn't seem to be able to help. imtest says that oxadmin can authenticate.

root@elise:/var/log/open-xchange# imtest -a oxadmin
WARNING: no hostname supplied, assuming localhost

S: * OK elise Cyrus IMAP4 v2.2.13 server ready
C: C01 CAPABILITY
S: * CAPABILITY IMAP4 IMAP4rev1 ACL QUOTA LITERAL+ MAILBOX-REFERRALS NAMESPACE UIDPLUS ID NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY SORT THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE IDLE STARTTLS
S: C01 OK Completed
Please enter your password:
C: L01 LOGIN oxadmin {12}
S: + go ahead
C: <omitted>
S: L01 OK User logged in
Authenticated.
Security strength factor: 0

I get this in /var/log/messages with every click on a user in the admin GUI:

Feb 26 15:38:33 elise imap[18768]: login: localhost [127.0.0.1] oxadmin plaintext User logged in

and this in /var/log/debug:

Feb 26 15:42:44 elise imap[18942]: accepted connection
Feb 26 15:42:44 elise master[18949]: about to exec /usr/cyrus/bin/timsieved
Feb 26 15:42:44 elise sieve[18949]: executed
Feb 26 15:42:44 elise sieve[18949]: accepted connection

I'm also getting the following in /var/log/open-xchange/open-xchange-admin.log.0 with every click on a user in the admin GUI:

Feb 26, 2008 11:17:53 PM com.openexchange.admin.rmi.impl.OXUserMailfilterImpl getData
SEVERE: Authentication failed
com.openexchange.admin.rmi.exceptions.OXSieveHandlerInvalidCredentialsException:
 Authentication failed
        at com.openexchange.admin.rmi.impl.SieveHandler.initializeConnection(Sie
veHandler.java:256)
        at com.openexchange.admin.rmi.impl.OXUserMailfilterImpl.getDataimpl(OXUs
erMailfilterImpl.java:706)
        at com.openexchange.admin.rmi.impl.OXUserMailfilterImpl.getData(OXUserMa
ilfilterImpl.java:242)
        at com.openexchange.admin.rmi.impl.OXUser.getData(OXUser.java:850)
        at com.openexchange.admin.rmi.impl.OXUser.getData(OXUser.java:728)
        at sun.reflect.GeneratedMethodAccessor107.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
sorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
        at sun.rmi.transport.Transport$1.run(Transport.java:159)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:5
35)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTranspor
t.java:790)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport
.java:649)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExec
utor.java:885)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor
.java:907)
        at java.lang.Thread.run(Thread.java:619)

[TomL]

timsieved broken?

It would seem that timesieved won't authenticate anyone, not just oxadmin.

root@elise:/var/log# sivtest -m plain -a toml
WARNING: no hostname supplied, assuming localhost

S: "IMPLEMENTATION" "Cyrus timsieved v2.2.13"
S: "SASL" "LOGIN PLAIN"
S: "SIEVE" "fileinto reject envelope vacation imapflags notify subaddress relational comparator-i;ascii-numeric regex"
S: "STARTTLS"
S: OK
Please enter your password:
C: AUTHENTICATE "PLAIN" {20+}
AHRvbWwAN2gwcnVwXg==
S: NO "Authentication Error"
Authentication failed. generic failure
Security strength factor: 0
C: LOGOUT
Connection closed.

sivtest -m plain -a oxadmin looks identical. Interestingly, without the "-m plain", sivtest tries AUTHENTICATE "LOGIN" and never prompts for a password at all, and emits an error about base64 decoding:

root@elise:/var/log# sivtest -a toml
WARNING: no hostname supplied, assuming localhost

S: "IMPLEMENTATION" "Cyrus timsieved v2.2.13"
S: "SASL" "LOGIN PLAIN"
S: "SIEVE" "fileinto reject envelope vacation imapflags notify subaddress relational comparator-i;ascii-numeric regex"
S: "STARTTLS"
S: OK
C: AUTHENTICATE "LOGIN"
S: {12}
S: VXNlcm5hbWU6
base64 decoding error
Authentication failed. generic failure
Security strength factor: 0
C: LOGOUT
Connection closed.

[TomL]

Update

I updated cyrus-imapd to the latest test version, 2.3.11 and that solved the base64 decode problem when sivtest tries LOGIN authentication. However, it still doesn't authenticate any user, with either LOGIN or PLAIN.

What, other than /etc/pam.d/* files, would cause imapd to authenticate and timsieved to not authenticate? My /etc/pam.d/imap and /etc/pam.d/sieve are identical.

It would be nice if I could get pam_mysql and timsieved to log some debug output....

[TomL]

Now we're getting somewhere...

I got pam_mysql to log some debug output. It still doesn't tell me why the pam setup isn't working for sieve, though. Below is output to /var/log/secure when I click on a user in the admin GUI. What's really funky is that when I look at the same debug output from an imap login, they are exactly identical, except for the time and process id.

Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option verbose is set to "1"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_close_db() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_sm_authenticate() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_open_db() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_open_db() returning 0.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_check_passwd() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_format_string() called
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_quick_escape() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - SELECT user.userPassword FROM login2user LEFT JOIN user ON login2user.id=user.id AND login2user.cid=user.cid WHERE login2user.uid = 'oxadmin' AND (user.cid=1)
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_check_passwd() returning 6.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_sql_log() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_sql_log() returning 0.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_converse() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_open_db() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_check_passwd() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_format_string() called
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_quick_escape() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - SELECT user.userPassword FROM login2user LEFT JOIN user ON login2user.id=user.id AND login2user.cid=user.cid WHERE login2user.uid = 'oxadmin' AND (user.cid=1)
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_check_passwd() returning 0.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_sql_log() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_sql_log() returning 0.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_sm_authenticate() returning 0.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option host is set to "localhost"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option user is set to "openexchange"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option passwd is set to "xxxxxxxxxxxxx"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option db is set to "open-xchange-db"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option table is set to "login2user LEFT JOIN user ON login2user.id=user.id AND login2user.cid=user.cid"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option where is set to "user.cid=1"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option usercolumn is set to "login2user.uid"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option passwdcolumn is set to "user.userPassword"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option crypt is set to "1"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - option verbose is set to "1"
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_close_db() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_sm_acct_mgmt() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_open_db() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_open_db() returning 0.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_query_user_stat() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_format_string() called
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_quick_escape() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - SELECT 0, user.userPassword FROM login2user LEFT JOIN user ON login2user.id=user.id AND login2user.cid=user.cid WHERE login2user.uid = 'oxadmin' AND (user.cid=1)
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_query_user_stat() returning 0.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_sql_log() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_sql_log() returning 0.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_sm_acct_mgmt() returning 0.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_release_ctx() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_destroy_ctx() called.
Feb 27 09:33:45 elise saslauthd[3021]: pam_mysql - pam_mysql_close_db() called.

[TomL]

pam_sm_authenticate

The important bit seems to be the return value of pam_sm_authenticate. When the authentication succeeds it returns a value of 0. I ran imtest and typed the wrong password on purpose just to see what it would log for a failure -- in that case, pam_sm_authenticate returns 7, and there's far fewer lines logged.

What I don't understand is, when sieve fails to authenticate, pam_sm_authenticate is returning 0! I can only surmise that the pam interface in sieve is different from the pam interface in imapd, to the point where its broken -- at least with respect to the version pam_mysql I have running (0.7RC1).

What version of pam_mysql is everyone using, and where did you get it? And what version of timsieved? And what version of pam itself? What about sasl?

My versions: pam 0.99.8.1, pam_mysql 0.7RC1, timsieved 2.3.11 (from cyrus-imapd 2.3.11), cyrus-sasl 2.1.22

[TomL]

saslauthd debug

saslauthd is seeing the "OK" from pam_mysql, but timsieved still fails to authenticate. This is what I get from saslauthd debug output when I click a user in the admin GUI:

saslauthd[20342] :rel_accept_lock : released accept lock
saslauthd[20346] :get_accept_lock : acquired accept lock
saslauthd[20342] :do_auth         : auth success: [user=oxadmin] [service=imap] [realm=] [mech=pam]
saslauthd[20342] :do_request      : response: OK
saslauthd[20346] :rel_accept_lock : released accept lock
saslauthd[20342] :get_accept_lock : acquired accept lock
saslauthd[20346] :do_auth         : auth success: [user=oxadmin] [service=sieve] [realm=] [mech=pam]
saslauthd[20346] :do_request      : response: OK

And this is what happens when I run imtest and type a bad password on purpose:

saslauthd[20342] :rel_accept_lock : released accept lock
saslauthd[20343] :get_accept_lock : acquired accept lock
saslauthd[20342] :do_auth         : auth failure: [user=toml] [service=imap] [realm=] [mech=pam] [reason=PAM auth error]

And yet in both cases, I get "authentication failed".

[TomL]

SOLVED!!!

So since no one was replying, I set about adding debug stuff to timsieved.c and its authentication command function in its parser.c to figure out what was going on.

In examining the code, I found quite a few calls to syslog with LOG_ERR -- but I wasn't logging those. I added a line of "*.err /var/log/error" to my /etc/syslog.conf, restarted the daemons, and tried things out.

What I saw (in my new /var/log/error file) was that timsieved was trying to create a directory under /usr/sieve with the first letter of the user trying to log in, and it couldn't because of permissions. When I created /usr/sieve and chowned it to the cyrus user -- voila! admin GUI now works properly, and as a bonus, so does timsieved.

Now to figure out if I can use MailScanner in postfix without wreaking havoc with open-xchange, and develop my migration strategy.

root@elise:/var/log# tail -f error
Feb 27 16:33:29 elise sieve[354]: IOERROR: creating directory /usr/sieve/t: Perm ission denied
Feb 27 16:33:29 elise sieve[354]: mkdir /usr/sieve/t: Permission denied
Feb 27 16:33:29 elise sieve[354]: error in actions_setuser()

[superstretch]

Had a very similar problem, except for me its /var/spool/sieve