Re: Centos 7: Postfix + cyrus-sasl (auxprop sql) fills systemdjournal with debug messages

[Patrick Wagner]

On Mon  18:29 , Viktor Dukhovni  wrote:

> On Mon, Oct 05, 2015 at 12:29:45PM +0200, Patrick Wagner wrote:
> > Everything's working fine, but smtpd produces dozens of debug
> > lines per SMTP AUTH, which makes the journald log quite
> unreadable:
> The logging is emitted by Cyrus SASL, not Postfix.

I suspected as much, but wanted to make sure.

> > Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin try and
> connect to a host
> > 
> > These messages are facility 'auth' and severity 'debug', so don't
> end up
> > in /var/log/maillog and I can just look there for mail-related
> messages,
> > but I'd still like to keep the clutter out of the journald log.
> Postfix logs with facility "mail", these syslog() calls are from
> inside the Cyrus library.
> > Setting the log_level to 0 in /etc/sasl2/smtpd.conf doesn't change
> anything.
> Perhaps you're editing the wrong file, or not running "postfix
> reload" to restart the affected processes.
> log_level: 0
> is the correct interface.

It's the correct file for sure, as changing the SQL connection parameters in 
the file to incorrect ones break SASL auth as expected, but log_level is 
ignored, at least as far as these debug messages are concerned.

I've now verified that I can see the exact same messages if I configure an 
auth.debug syslog output in rsyslog on the original Ubuntu 12.04 server as 
well, and the Ubuntu server is unimpressed by  "log_level: 0" as well and 
continues logging the SQL debug messages into said log file, so this is indeed 
unrelated to CentOS or its cyrus-sasl package and I notice it only just now 
because Ubuntu with its default rsyslog settings doesn't log auth.debug (or 
*.debug, for that matter) messages anywhere, while they will all naturally end 
up in systemd. 

Oh, and I found the following post on the cyrusl-sasl mailing list, posted by 
Alexej Melnikov in 2006 - so there was (still is?) maybe something special 
about Postfix's handling of cyrus-sasl?
http://lists.andrew.cmu.edu/pipermail/cyrus-sasl/2006-April/000377.html

Here's my cyrus-sasl smtpd.conf, for reference:

pwcheck_method: auxprop
auxprop_plugin: sql
mech_list: PLAIN LOGIN CRAM-MD5 DIGEST-MD5
sql_engine: mysql
sql_hostnames: 127.0.0.1:33306
sql_user: dbusername
sql_passwd: dbsecretpw
sql_database: postfix
sql_select: SELECT passwd FROM sasl WHERE uname = '%u'
log_level: 0


--
Patrick Wagner

Re: Centos 7: Postfix + cyrus-sasl (auxprop sql) fills systemdjournal with debug messages

[Viktor Dukhovni]

On Mon, Oct 05, 2015 at 10:39:54PM +0200, Patrick Wagner wrote:

> Oh, and I found the following post on the cyrusl-sasl mailing list, posted by 
> Alexej Melnikov in 2006 - so there was (still is?) maybe something special 
> about Postfix's handling of cyrus-sasl?
> http://lists.andrew.cmu.edu/pipermail/cyrus-sasl/2006-April/000377.html

The Postfix callback only logs debug messages if "msg_verbose >
0", i.e. you've enabled verbose logging in Postfix with "-v" in
master.cf or debug_peer_list, ...

This is indeed insensitive to the log_level in the SASL configuration
file.  Otherwise for debug logging you'd need both "-v" in Postfix,
and a high debug level in the SASL config file.

Note however, that Postfix logging of Cyrus debug messages is tagged
with prefixes:

msg_info("SASL authentication info: %s", message);
msg_info("SASL authentication info: %s", message);
msg_info("SASL authentication debug: %s", message);
msg_info("SASL authentication trace: %s", message);
msg_info("SASL authentication pass: %s", message);

you did not report any such prefixes in your log samples.

Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin try and connect to a 
host

Furthermore, you report messages in the "auth" log, but Postfix
logs to the mail log.

So the conclusion is that Cyrus is logging directly to syslog,
bypassing the Postfix logging callback.  Looks like something
similar to:

http://lists.andrew.cmu.edu/pipermail/cyrus-sasl/2011-February/002185.html

Indeed looking at plugins/sql.c in a recent Debian Cyrus SASL package I see:

sparams->utils->log(NULL, SASL_LOG_DEBUG,
sparams->utils->log(NULL, SASL_LOG_DEBUG, "begin transaction");
sparams->utils->log(NULL, SASL_LOG_DEBUG, "commit transaction");
utils->log(NULL, SASL_LOG_DEBUG,
utils->log(NULL, SASL_LOG_DEBUG, "sql freeing memory\n");
utils->log(NULL, SASL_LOG_DEBUG, "sql plugin: %d", rc);
utils->log(NULL, SASL_LOG_DEBUG, "sql plugin: %s ",
utils->log(NULL, SASL_LOG_DEBUG, "sql plugin: %s ", zErrMsg);
utils->log(NULL, SASL_LOG_DEBUG, "sql plugin: %s", zErrMsg);

That NULL, should be the connection handle, so that the Postfix
callback is actually found!  This bug seems to be present in the
latest commits at

https://cgit.cyrus.foundation/cyrus-sasl/tree/plugins/sql.c

Can you take this to the Cyrus IMAP list, or the Debian/Ubuntu
maintainers?

-- 
Viktor.

Re: Centos 7: Postfix + cyrus-sasl (auxprop sql) fills systemdjournal with debug messages

[Viktor Dukhovni]

On Mon, Oct 05, 2015 at 10:05:14PM +, Viktor Dukhovni wrote:

Can you take this to the Cyrus IMAP list, or the Debian/Ubuntu
maintainers?

Proposed patch below.  Other plugins require similar treatment.

As for Postfix, perhaps "msg_verbose" should not alone be sufficient
to trigger password logging?  We could require "msg_verbose" *and*
an smtpd.conf with log_level set high enough, via code along the
lines suggested by Alexey.

-- 
Viktor.

diff --git a/plugins/sql.c b/plugins/sql.c
index 3b89383..7992b05 100644
--- a/plugins/sql.c
+++ b/plugins/sql.c
@@ -73,3 +73,3 @@ static void *_mysql_open(char *host, char *port, int usessl,
 if (!(mysql = mysql_init(NULL))) {
-   utils->log(NULL, SASL_LOG_ERR,
+   utils->log(utils->conn, SASL_LOG_ERR,
   "sql plugin: could not execute mysql_init()");
@@ -110,3 +110,3 @@ static int _mysql_exec(void *conn, const char *cmd, char 
*value, size_t size,
 if(mysql_errno(conn)) {
-utils->log(NULL, SASL_LOG_ERR, "sql query failed: %s",
+utils->log(utils->conn, SASL_LOG_ERR, "sql query failed: %s",
   mysql_error(conn));
@@ -125,3 +125,3 @@ static int _mysql_exec(void *conn, const char *cmd, char 
*value, size_t size,
/* umm nothing found */
-   utils->log(NULL, SASL_LOG_NOTE, "sql plugin: no result found");
+   utils->log(utils->conn, SASL_LOG_NOTE, "sql plugin: no result found");
return -1;
@@ -134,3 +134,3 @@ static int _mysql_exec(void *conn, const char *cmd, char 
*value, size_t size,
mysql_free_result(result);
-   utils->log(NULL, SASL_LOG_NOTE, "sql plugin: no result found");
+   utils->log(utils->conn, SASL_LOG_NOTE, "sql plugin: no result found");
return -1;
@@ -138,3 +138,3 @@ static int _mysql_exec(void *conn, const char *cmd, char 
*value, size_t size,
 if (row_count > 1) {
-   utils->log(NULL, SASL_LOG_WARN,
+   utils->log(utils->conn, SASL_LOG_WARN,
   "sql plugin: found duplicate row for query %s", cmd);
@@ -147,3 +147,3 @@ static int _mysql_exec(void *conn, const char *cmd, char 
*value, size_t size,
/* umm nothing found */
-   utils->log(NULL, SASL_LOG_NOTE, "sql plugin: no result found");
+   utils->log(utils->conn, SASL_LOG_NOTE, "sql plugin: no result found");
mysql_free_result(result);
@@ -259,3 +259,4 @@ static void *_pgsql_open(char *host, char *port, int usessl,
 if ((PQstatus(conn) != CONNECTION_OK)) {
-   utils->log(NULL, SASL_LOG_ERR, "sql plugin: %s", PQerrorMessage(conn));
+   utils->log(utils->conn, SASL_LOG_ERR, "sql plugin: %s",
+  PQerrorMessage(conn));
return NULL;
@@ -290,3 +291,3 @@ static int _pgsql_exec(void *conn, const char *cmd, char 
*value, size_t size,
/* error */
-   utils->log(NULL, SASL_LOG_DEBUG, "sql plugin: %s ",
+   utils->log(utils->conn, SASL_LOG_DEBUG, "sql plugin: %s ",
   PQresStatus(status));
@@ -300,3 +301,3 @@ static int _pgsql_exec(void *conn, const char *cmd, char 
*value, size_t size,
/* umm nothing found */
-   utils->log(NULL, SASL_LOG_NOTE, "sql plugin: no result found");
+   utils->log(utils->conn, SASL_LOG_NOTE, "sql plugin: no result found");
PQclear(result);
@@ -305,3 +306,3 @@ static int _pgsql_exec(void *conn, const char *cmd, char 
*value, size_t size,
 if (row_count > 1) {
-   utils->log(NULL, SASL_LOG_WARN,
+   utils->log(utils->conn, SASL_LOG_WARN,
   "sql plugin: found duplicate row for query %s", cmd);
@@ -359,3 +360,3 @@ static void *_sqlite_open(char *host 
__attribute__((unused)),
 if (db == NULL) {
-   utils->log(NULL, SASL_LOG_ERR, "sql plugin: %s", zErrMsg);
+   utils->log(utils->conn, SASL_LOG_ERR, "sql plugin: %s", zErrMsg);
sqlite_freemem (zErrMsg);
@@ -366,3 +367,3 @@ static void *_sqlite_open(char *host 
__attribute__((unused)),
 if (rc != SQLITE_OK) {
-   utils->log(NULL, SASL_LOG_ERR, "sql plugin: %s", zErrMsg);
+   utils->log(utils->conn, SASL_LOG_ERR, "sql plugin: %s", zErrMsg);
sqlite_freemem (zErrMsg);
@@ -416,3 +417,3 @@ static int _sqlite_exec(void *db, const char *cmd, char 
*value, size_t size,
 if (rc != SQLITE_OK && rc != SQLITE_ABORT) {
-   utils->log(NULL, SASL_LOG_DEBUG, "sql plugin: %s ", zErrMsg);
+   utils->log(utils->conn, SASL_LOG_DEBUG, "sql plugin: %s ", zErrMsg);
sqlite_freemem (zErrMsg);
@@ -428,3 +429,3 @@ static int _sqlite_exec(void *db, const char *cmd, char 
*value, size_t size,
/* umm nothing found */
-   utils->log(NULL, SASL_LOG_NOTE, "sql plugin: no result found");
+   utils->log(utils->conn, SASL_LOG_NOTE, "sql plugin: no result found");
return -1;
@@ -487,5 +488,6 @@ static void *_sqlite3_open(char *host 
__attribute__((unused)),
if (db)
-   utils->log(NULL, SASL_LOG_ERR, "sql plugin: %s", 
sqlite3_errmsg(db));
+   utils->log(utils->conn,