(no subject)

• Previous message: Mark London: "Re: I lost my SMTP AUTH, help!"
• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ] [ attachment ]

I'm fighting a rather weird problem with our Cyrus mail server and I believe
I have tracked the problem to the Cyrus SASL library, but am stuck at this
point.

About two months ago, our customers started to complain that webmail was not
working and the webmail client (IMP) was randomly logging them out for no
apparent reason during a normal session. Also other mail clients had sometimes
trouble logging in, their session was simply stuck during login.

It took quite some time to track the problem to our Cyrus server. I finally
did a tcpdump and saw this monstrosity (below is an example of a manual login
that I did to demonstrate the problem):

* OK piranha.amis.net Cyrus IMAP4 v2.2.3 server ready
. authenticate cram-md5
+ PDI0NzA0OTc2MTIuMTMxMzQwMzhAcGlyYW5oYS5hbWlzLm5ldD4=
YmxheiBkM2UyZWQxNTA2OGNhOWU2NTYzMzhmNWE1ZDcxNjhkMA==
<39>Jun 10 15:56:44 imap[12935]: sql plugin Parse the username blaz
<39>Jun 10 15:56:44 imap[12935]: sql plugin try and connect to a host
<39>Jun 10 15:56:44 imap[12935]: sql plugin trying to open db 'medinet' on
host 'db2.amis.net'
<39>Jun 10 15:56:44 imap[12935]: begin transaction<39>Jun 10 15:56:44
imap[12935]: sql plugin create statement from userPasswo
rd blaz piranha.amis.net
<39>Jun 10 15:56:44 imap[12935]: sql plugin doing query select geslo from
eposta where dostava='blaz' and tip='predal' and opc
ije not like '%izkljucen%' and geslo is not null;
<39>Jun 10 15:56:44 imap[12935]: sql plugin create statement from
cmusaslsecretCRAM-MD5 blaz piranha.amis.net
<39>Jun 10 15:56:44 imap[12935]: sql plugin doing query select geslo from
eposta where dostava='blaz' and tip='predal' and opc
ije not like '%izkljucen%' and geslo is not null;
<39>Jun 10 15:56:44 imap[12935]: commit transaction<39>Jun 10 15:56:44
imap[12935]: sql plugin Parse the username blaz
<39>Jun 10 15:56:44 imap[12935]: sql plugin try and connect to a host
<39>Jun 10 15:56:44 imap[12935]: sql plugin trying to open db 'medinet' on
host 'db2.amis.net'
<181>Jun 10 15:56:44 imap[12935]: login: titanic.medinet.si [212.18.42.5] blaz
cram-md5 User logged in. OK Success (no protect
ion)
. logout
* BYE LOGOUT received
. OK Completed

As you can see, the IMAP conversation contains part of the log. Why the hell
is Cyrus logging this junk to the session? This happens randomly and usually
starts about 5 to 10 minutes after the Cyrus mail server is started up. Of
course this highly confuses mail clients which expect an "OK" reply to the
AUTHENTICATE command, but instead receive the junk above before the "OK".
Usually the clients get confused and later time out and display a "password
incorrect" or simmilar message, which is obviously very annoying for the
users.

I traced the above output to the cyrus-sasl/plugins/sql.c file. All of the
above lines are logged at SASL_LOG_DEBUG level. I've looked around the SASL
source and see that logging is handled using callbacks. As far as I can see,
the default logging callback is syslog, so the above should be logged to
syslog, which does not log anything at *.debug level.

The interesting part is, that only lines with SASL_LOG_DEBUG level are output
to the IMAP session, and then only randomly, not for every session. There are
other lines in sql.c that log for example at SASL_LOG_ERROR or
SASL_LOG_NOTICE, none of those are in the buggy session output, all of them
are correctly logged to /var/log/messages.

Any idea what is going on here? Server is FreeBSD 4.10, Cyrus IMAPD 2.2.5 (was
using 2.1.X previously with the same result), Cyrus SASL 2.1.18.

For now, I have just commented out the relevant lines to fix the problem, but
this is obviously only a quick hack. I'd really like to find out the root
cause of the problem which very much looks like a bug in Cyrus SASL.

--- plugins/sql.c.orig Thu Jan 8 16:30:26 2004
+++ plugins/sql.c Fri Jun 11 10:08:40 2004
@@ -279,8 +279,8 @@
     }
     else if (status != PGRES_TUPLES_OK) {
         /* error */
- utils->log(NULL, SASL_LOG_DEBUG, "sql plugin: %s ",
- PQresStatus(status));
+// utils->log(NULL, SASL_LOG_DEBUG, "sql plugin: %s ",
+// PQresStatus(status));
         PQclear(result);
         return -1;
     }
@@ -559,8 +559,8 @@
      * it should probably save the connection but for
      * now we will just disconnect everytime
      */
- utils->log(NULL, SASL_LOG_DEBUG,
- "sql plugin try and connect to a host\n");
+// utils->log(NULL, SASL_LOG_DEBUG,
+// "sql plugin try and connect to a host\n");

     /* create a working version of the hostnames */
     _plug_strdup(utils, settings->sql_hostnames, &db_host_ptr, NULL);
@@ -575,10 +575,10 @@
             while (!isalnum(db_host[0])) db_host++;
         }

- utils->log(NULL, SASL_LOG_DEBUG,
- "sql plugin trying to open db '%s' on host '%s'%s\n",
- settings->sql_database, cur_host,
- settings->sql_usessl ? " using SSL" : "");
+// utils->log(NULL, SASL_LOG_DEBUG,
+// "sql plugin trying to open db '%s' on host '%s'%s\n",
+// settings->sql_database, cur_host,
+// settings->sql_usessl ? " using SSL" : "");

         /* set the optional port */
         if ((cur_port = strchr(cur_host, ':'))) *cur_port++ = '\0';
@@ -629,8 +629,8 @@
     /* setup the settings */
     settings = (sql_settings_t *) glob_context;

- sparams->utils->log(NULL, SASL_LOG_DEBUG,
- "sql plugin Parse the username %s\n", user);
+// sparams->utils->log(NULL, SASL_LOG_DEBUG,
+// "sql plugin Parse the username %s\n", user);

     user_buf = sparams->utils->malloc(ulen + 1);
     if (!user_buf) goto done;
@@ -700,16 +700,16 @@

         if (!do_txn) {
             do_txn = 1;
- sparams->utils->log(NULL, SASL_LOG_DEBUG, "begin transaction");
+// sparams->utils->log(NULL, SASL_LOG_DEBUG, "begin transaction");
             if (settings->sql_engine->sql_begin_txn(conn, sparams->utils)) {
                 sparams->utils->log(NULL, SASL_LOG_ERR,
                                     "Unable to begin transaction\n");
             }
         }

- sparams->utils->log(NULL, SASL_LOG_DEBUG,
- "sql plugin create statement from %s %s %s\n",
- realname, escap_userid, escap_realm);
+// sparams->utils->log(NULL, SASL_LOG_DEBUG,
+// "sql plugin create statement from %s %s %s\n",
+// realname, escap_userid, escap_realm);

         /* create a statement that we will use */
         query = sql_create_statement(settings->sql_select,
@@ -717,8 +717,8 @@
                                      escap_realm, NULL,
                                      sparams->utils);

- sparams->utils->log(NULL, SASL_LOG_DEBUG,
- "sql plugin doing query %s\n", query);
+// sparams->utils->log(NULL, SASL_LOG_DEBUG,
+// "sql plugin doing query %s\n", query);

         /* run the query */
         if (!settings->sql_engine->sql_exec(conn, query, value, sizeof(value),
@@ -731,7 +731,7 @@
     }

     if (do_txn) {
- sparams->utils->log(NULL, SASL_LOG_DEBUG, "commit transaction");
+// sparams->utils->log(NULL, SASL_LOG_DEBUG, "commit transaction");
         if (settings->sql_engine->sql_commit_txn(conn, sparams->utils)) {
             sparams->utils->log(NULL, SASL_LOG_ERR,
                                 "Unable to commit transaction\n");
@@ -778,8 +778,8 @@
     /* make sure our input is okay */
     if (!glob_context || !sparams || !user) return SASL_BADPARAM;

- sparams->utils->log(NULL, SASL_LOG_DEBUG,
- "sql plugin Parse the username %s\n", user);
+// sparams->utils->log(NULL, SASL_LOG_DEBUG,
+// "sql plugin Parse the username %s\n", user);

     user_buf = sparams->utils->malloc(ulen + 1);
     if (!user_buf) {
@@ -865,9 +865,9 @@
                                      cur->values && cur->values[0] ?
                                      "<omitted>" : SQL_NULL_VALUE,
                                      sparams->utils);
- sparams->utils->log(NULL, SASL_LOG_DEBUG,
- "sql plugin doing statement %s\n",
- log_statement);
+// sparams->utils->log(NULL, SASL_LOG_DEBUG,
+// "sql plugin doing statement %s\n",
+// log_statement);
             sparams->utils->free(log_statement);
         }

@@ -914,7 +914,7 @@

     if (!settings) return;

- utils->log(NULL, SASL_LOG_DEBUG, "sql freeing memory\n");
+// utils->log(NULL, SASL_LOG_DEBUG, "sql freeing memory\n");

     utils->free(settings);
 }
@@ -961,9 +961,9 @@
         return SASL_NOMECH;
     }

- utils->log(NULL, SASL_LOG_DEBUG,
- "sql auxprop plugin using %s engine\n",
- settings->sql_engine->name);
+// utils->log(NULL, SASL_LOG_DEBUG,
+// "sql auxprop plugin using %s engine\n",
+// settings->sql_engine->name);

     sql_auxprop_plugin.glob_context = settings;

• Previous message: Mark London: "Re: I lost my SMTP AUTH, help!"
• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ] [ attachment ]