(no subject)

From: Blaz Zupan (blaz at inlimbo dot org)
Date: Fri Jun 11 2004 - 04:31:40 EDT

  • Next message: Jason Novak: "saslauthd PAM authentication mechanism does not exist"

    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;


  • Next message: Jason Novak: "saslauthd PAM authentication mechanism does not exist"





    Hosted Email Solutions

    Invaluement Anti-Spam DNSBLs



    Powered By FreeBSD   Powered By FreeBSD