Re: SASL auth failure dovecot/postfix
On Tue, Mar 11, 2014 at 04:35:51PM +0000, Tom Furie wrote:
> On Tue, Mar 11, 2014 at 04:22:45PM +0100, Tazman Deville wrote:
>
> > They both use mysql (well, mariadb) auth for both dovecot and
> > postfix.
> > I have confirmed that I can connect to the DB on either server with
> > the
> > mail admin account configured in postfix.
> > Yet, I can not send mail.
>
> Do they connect to the same database for authentication against both
> dovecot and postfix? Can you connect to the database as a normal user?
> How many users are having the problem?
There are few users on either server, and all I've tested are unable to
send mail.
In both servers, there is 1 mail DB for both dovecot and postfix, yes.
> > As far as I recall, postfix was not updated yesterday.
> > Nor was mariadb, dovecot, or anything else I can imagine is
> > significant
> > here. Aside from mail, the servers have slightly different software
> > installed. One received 1 update, the other 3.
> > I do not believe they were the same at all (as in the 1 update one
> > the
> > first server was not the same as any of the 3 on the other).
>
> It might help to know exactly which packages were updated -
> /var/log/apt/{history,term}.log and /var/log/dpkg.log
> should have the information.
tail history.log for one of the servers:
Start-Date: 2014-03-04 15:30:45
Upgrade: mariadb-server:i386 (5.5.35+maria-1~wheezy,
5.5.36+maria-1~wheezy), php5:i386 (5.4.4-14+deb7u7, 5.4.4-14+deb7u8),
php5-sqlite:i386 (5.4.4-14+deb7u7, 5.4.4-14+deb7u8), mysql-common:i386
(5.5.35+maria-1~wheezy, 5.5.36+maria-1~wheezy), libgnutls26:i386
(2.12.20-7, 2.12.20-8+deb7u1), php5-gd:i386 (5.4.4-14+deb7u7,
5.4.4-14+deb7u8), xulrunner-27:i386 (27.0-2~bpo70+1, 27.0.1-1~bpo70+1),
php-pear:i386 (5.4.4-14+deb7u7, 5.4.4-14+deb7u8), iceweasel:i386
(27.0-2~bpo70+1, 27.0.1-1~bpo70+1), php5-curl:i386 (5.4.4-14+deb7u7,
5.4.4-14+deb7u8), libmozjs-dev:i386 (27.0-2~bpo70+1, 27.0.1-1~bpo70+1),
mariadb-client:i386 (5.5.35+maria-1~wheezy, 5.5.36+maria-1~wheezy),
libmozjs27d:i386 (27.0-2~bpo70+1, 27.0.1-1~bpo70+1),
libmariadbclient18:i386 (5.5.35+maria-1~wheezy, 5.5.36+maria-1~wheezy),
mariadb-server-core-5.5:i386 (5.5.35+maria-1~wheezy,
5.5.36+maria-1~wheezy), php5-mcrypt:i386 (5.4.4-14+deb7u7,
5.4.4-14+deb7u8), libmysqlclient18:i386 (5.5.35+maria-1~wheezy,
5.5.36+maria-1~wheezy), php5-intl:i386 (5.4.4-14+deb7u7,
5.4.4-14+deb7u8), mariadb-common:i386 (5.5.35+maria-1~wheezy,
5.5.36+maria-1~wheezy), php5-mysql:i386 (5.4.4-14+deb7u7,
5.4.4-14+deb7u8), php5-cli:i386 (5.4.4-14+deb7u7, 5.4.4-14+deb7u8),
mariadb-server-5.5:i386 (5.5.35+maria-1~wheezy, 5.5.36+maria-1~wheezy),
mariadb-client-core-5.5:i386 (5.5.35+maria-1~wheezy,
5.5.36+maria-1~wheezy), libapache2-mod-php5:i386 (5.4.4-14+deb7u7,
5.4.4-14+deb7u8), mariadb-client-5.5:i386 (5.5.35+maria-1~wheezy,
5.5.36+maria-1~wheezy), php5-common:i386 (5.4.4-14+deb7u7,
5.4.4-14+deb7u8), xulrunner-dev:i386 (27.0-2~bpo70+1, 27.0.1-1~bpo70+1)
End-Date: 2014-03-04 15:32:56
Start-Date: 2014-03-10 23:32:28
Upgrade: udisks:i386 (1.0.4-7, 1.0.4-7wheezy1)
End-Date: 2014-03-10 23:32:50
I thought that might be getting us somewhere, since mariadb is in
there,
but that was on the 4th, and the server was working until today, the
11th.
Now tail term.log for the same server as above:
Processing triggers for menu ...
Log ended: 2014-03-04 15:32:56
Log started: 2014-03-10 23:32:28
(Reading database ... 220649 files and directories currently
installed.)
Preparing to replace udisks 1.0.4-7 (using
.../udisks_1.0.4-7wheezy1_i386.deb) ...
Unpacking replacement udisks ...
Processing triggers for man-db ...
Setting up udisks (1.0.4-7wheezy1) ...
Log ended: 2014-03-10 23:32:50
The other servers shows the same updates on the 4th, plus this from the
10th in history.log:
Start-Date: 2014-03-10 23:13:25
Upgrade: libyaml-libyaml-perl:amd64 (0.38-3, 0.38-3+deb7u1)
End-Date: 2014-03-10 23:13:37
and this in tail term.log
[ ok ] Reloading web server config: apache2.
Log ended: 2014-03-04 21:32:51
Log started: 2014-03-10 23:13:25
(Reading database ... 90014 files and directories currently installed.)
Preparing to replace libyaml-libyaml-perl 0.38-3 (using
.../libyaml-libyaml-perl_0.38-3+deb7u1_amd64.deb) ...
Unpacking replacement libyaml-libyaml-perl ...
Processing triggers for man-db ...
Setting up libyaml-libyaml-perl (0.38-3+deb7u1) ...
Log ended: 2014-03-10 23:13:37
So the updates they received yesterday don't look relevant,
but they were both working until today.
I've tried using mutt here from my desktop, and also on each server
over
ssh, plus, they both have squirrelmail on the servers, and I've tried
that. In all cases, I am receiving mail normally and can log in an read
it, but can not send anything out.
>
> > Still, they're having apparently identical problems now, and the
> > only
> > thing that has changed on either since they were working was
> > running the
:> > aptitude updates.
> > All the logs seem to be telling me is that SASL auth is failing,
> > which I know. They do not tell me why or wherein lies the failure.
>
> Does /var/log/auth.log have any further details?
Ah! Perhaps this will be useful.
I just logged in with mutt, received mail, and tried to send one
message, and get this from tail auth.log:
Mar 11 19:33:32 myownsite postfix/smtpd[32642]: sql plugin Parse the
username taz@liberame.org
Mar 11 19:33:32 myownsite postfix/smtpd[32642]: sql plugin try and
connect to a host
Mar 11 19:33:32 myownsite postfix/smtpd[32642]: sql plugin trying to
open db 'mail' on host '127.0.0.1'
Mar 11 19:33:32 myownsite saslauthd[1850]: PAM unable to
dlopen(pam_mysql.so): /lib/security/pam_mysql.so: symbol
make_scrambled_password, version libmysqlclient_18 not defined in file
libmysqlclient.so.18 with link time reference
Mar 11 19:33:32 myownsite saslauthd[1850]: PAM adding faulty module:
pam_mysql.so
Mar 11 19:33:32 myownsite saslauthd[1850]: DEBUG: auth_pam:
pam_authenticate failed: Module is unknown
Mar 11 19:33:32 myownsite saslauthd[1850]: do_auth : auth
failure: [user=taz@liberame.org] [service=smtp] [realm=liberame.org]
[mech=pam] [reason=PAM auth error]
Mar 11 19:33:37 myownsite mutt: DIGEST-MD5 common mech free
Mar 11 19:33:40 myownsite sudo: tazman : TTY=pts/0 ; PWD=/var/log ;
USER=root ; COMMAND=/usr/bin/tail auth.log
Mar 11 19:33:40 myownsite sudo: pam_unix(sudo:session): session opened
for user root by tazman(uid=0)
taz
:wq
--
http://taz.liberame.org
Reply to: