Centos 7: Postfix + cyrus-sasl (auxprop sql) fills systemd journal with debug messages
Hello everybody, I'm in the process of migrating a postfix + cyrus-sasl configuration from Ubuntu 12.04 to CentOS 7.1 I'm using the cyrus-sasl-plain and cyrus-sasl-sql packages to enable AUTH LOGIN against a SQL backend (pwcheck_method: auxprop, auxprop_plugin: sql) Everything's working fine, but smtpd produces dozens of debug lines per SMTP AUTH, which makes the journald log quite unreadable: Oct 05 11:55:01 mail postfix/smtpd[5883]: sql auxprop plugin using mysql engine Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin Parse the username sasl-user Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin try and connect to a host Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin trying to open db 'postfix' on host '127.0.0.1:3306' Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin create statement from userPassword sasl-user mail.domain Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin doing query SELECT passwd FROM saslout WHERE uname='sasl-user' AND aktiv='Y'; Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin Parse the username sasl-user Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin try and connect to a host Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin trying to open db 'postfix' on host '127.0.0.1:3306' Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin Parse the username sasl-user Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin try and connect to a host Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin trying to open db 'postfix' on host '127.0.0.1:3306' Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin create statement from userPassword sasl-user mail.domain Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin doing query SELECT passwd FROM saslout WHERE uname='sasl-user' AND aktiv='Y'; Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin create statement from cmusaslsecretPLAIN sasl-user mail.domain Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin doing query SELECT passwd FROM saslout WHERE uname='sasl-user' AND aktiv='Y'; Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin Parse the username sasl-user Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin try and connect to a host Oct 05 11:55:01 mail postfix/smtpd[5883]: sql plugin trying to open db 'postfix' on host '127.0.0.1:3306' 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. Setting the log_level to 0 in /etc/sasl2/smtpd.conf doesn't change anything. Can anyone confirm or tell me how disable the debug messages? -- Patrick Wagner
Re: Centos 7: Postfix + cyrus-sasl (auxprop sql) fills systemd journal with debug messages
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. > 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. -- Viktor.
Re: Centos 7: Postfix + cyrus-sasl (auxprop sql) fills systemdjournal with debug messages
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
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
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, SASL_LOG_ERR,
postgresql table does not exist error
hi everyone i have installed and configured postgresql postfix and dovecot on arch linux the database called mail has this table and is owned by mailreader CREATE TABLE "al" ( alias text NOT NULL, email text NOT NULL ); the postfix file (/etc/postfix/pgsql-aliases.cf) has this hosts = /run/postgresql/ user = mailreader dbname = mail query = SELECT alias FROM "al" WHERE email='%s' (postgresql log file) ERROR: relation "al" does not exist at character 19 STATEMENT: SELECT alias FROM "al" WHERE email='ivy.tissisat.co.uk' (postfix log) Oct 05 18:19:33 testy postfix/smtpd[801]: connect from localhost.localdomain[127.0.0.1] Oct 05 18:20:21 testy postfix/proxymap[802]: warning: pgsql query failed: fatal error from host /run/postgresql: ERROR: relation "al" does not exist?LINE 1: SELECT alias FROM "al" WHERE email='ivy.tissi Oct 05 18:20:21 testy postfix/trivial-rewrite[805]: warning: virtual_alias_domains: proxy:pgsql:/etc/postfix/pgsql-aliases.cf: table lookup problem Oct 05 18:20:21 testy postfix/trivial-rewrite[805]: warning: virtual_alias_domains lookup failure Oct 05 18:21:07 testy postfix/trivial-rewrite[805]: warning: virtual_alias_domains: proxy:pgsql:/etc/postfix/pgsql-aliases.cf: table lookup problem Oct 05 18:21:07 testy postfix/trivial-rewrite[805]: warning: virtual_alias_domains lookup failure Oct 05 18:21:07 testy postfix/smtpd[801]: NOQUEUE: reject: RCPT from localhost.localdomain[127.0.0.1]: 451 4.3.0 : Temporary lookup failure; from= to= proto=ESMTP helo= Oct 05 18:26:07 testy postfix/smtpd[801]: timeout after RCPT from localhost.localdomain[127.0.0.1] Oct 05 18:26:07 testy postfix/smtpd[801]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 mail=1 rcpt=0/1 commands=2/3 i have read about quoting and case folding in postgresql my original table name and references to it was in lower case and without quotes so i recreated a new table with name lowercase characters with quotes and referenced the table with quotes and i still have the same errors. i also changed the host line to localhost in /etc/postfix/pgsql-aliases.cf and the error still occurs any sugestions what the problem might be ? shadrock
Re: postgresql table does not exist error
Hi, >the postfix file (/etc/postfix/pgsql-aliases.cf) has this > >hosts = /run/postgresql/ You should specify the socket to use. >From http://www.postfix.org/pgsql_table.5.html hosts The hosts that Postfix will try to connect to and query from. Specify unix: for UNIX-domain sockets, inet: for TCP connections (default). Example: hosts = host1.some.domain host2.some.domain:port hosts = unix:/file/name The hosts are tried in random order, with all connections over UNIX domain sockets being tried before those over TCP. The con- nections are automatically closed after being idle for about 1 minute, and are re-opened as necessary. NOTE: the unix: and inet: prefixes are accepted for backwards compatibility reasons, but are actually ignored. The PostgreSQL client library will always try to connect to an UNIX socket if the name starts with a slash, and will try a TCP connection otherwise. >user = mailreader >dbname = mail >query = SELECT alias FROM "al" WHERE email='%s' Regards - christian