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

[Viktor Dukhovni]

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: postgresql table does not exist error

[Christian Kivalo]

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

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.

postgresql table does not exist error

[niya levi]

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: 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, 

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

[Patrick Wagner]

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