Issues in the current HEAD

salv...@gmx.ch

unread,

Jan 3, 2015, 10:30:02 AM1/3/15

to qps...@perl.org

Hi,

I'm a long-time happy user of qpsmtpd with a small site, and right now I'm in the process of setting up my site on a new server and reinstalling qpsmtpd. I want to use auth_imap, which is in HEAD but not in 0.94, so I decided to try HEAD, but HEAD is broken: it does not announce "AUTH" at all. So I went for commit ee01a07 (2014-12-22 15:01:12 -0800), except for the following issue:

I've configured

logging/file:0 loglevel LOGEMERG nosplit tsformat %Y-%m-%d_%H:%M:%S /var/log/qpsmtpd/0-emergency-%Y.log
logging/file:1 loglevel LOGALERT nosplit tsformat %Y-%m-%d_%H:%M:%S /var/log/qpsmtpd/1-alert-%Y.log
logging/file:2 loglevel LOGCRIT nosplit tsformat %Y-%m-%d_%H:%M:%S /var/log/qpsmtpd/2-crit-%Y-%m.log
logging/file:3 loglevel LOGERROR nosplit tsformat %Y-%m-%d_%H:%M:%S /var/log/qpsmtpd/3-error-%Y-%m.log
logging/file:4 loglevel LOGWARN nosplit tsformat %Y-%m-%d_%H:%M:%S /var/log/qpsmtpd/4-warn-%Y-%m-%d.log
logging/file:5 loglevel LOGNOTICE nosplit tsformat %Y-%m-%d_%H:%M:%S /var/log/qpsmtpd/5-notice-%Y-%m-%d.log
logging/file:6 loglevel LOGINFO nosplit tsformat %Y-%m-%d_%H:%M:%S /var/log/qpsmtpd/6-info-%Y-%m-%d.log

and each instance generates one

FATAL PLUGIN ERROR [logging::file_3aX]: Can't call method "hook_logging" on unblessed reference at lib/Qpsmtpd/Plugin.pm line 47 during global destruction.

message, sometimes followed by a single

Can't call method "warn_handler" on an undefined value at /home/smtpd/qpsmtpd/qpsmtpd line 20 during global destruction.

message.

This occurs both in HEAD and in commit ee01a07 (2014-12-22 15:01:12 -0800).

Aside of that I'm excited to see all the new stuff in qpsmtpd, especially for SPF/DKIM/DMARC, which I had implemented outside of qpsmtpd on the old site.

Thank you for all your work!
Hans

salv...@gmx.ch

unread,

Jan 3, 2015, 6:30:01 PM1/3/15

to qps...@perl.org

I'm using xinetd according to http://wiki.qpsmtpd.org/doku.php?id=deploy:start, i.e. no daemon mode but just running

exec qpsmtpd

-----Ursprüngliche Nachricht-----
Gesendet: Saturday, 03 January 2015 um 23:31:06 Uhr
Von: "Jared Johnson" <jjoh...@efolder.net>
An: "salv...@gmx.ch" <salv...@gmx.ch>
Betreff: Re: Issues in the current HEAD

What daemon mode are you using? Prefork?

Jared Johnson

unread,

Jan 4, 2015, 12:30:02 AM1/4/15

to salv...@gmx.ch, qps...@perl.org

Regarding the warn_handler message, I probably managed to mess up my recently merged https://github.com/smtpd/qpsmtpd/pull/168 for xinetd mode. Unfortunately my availability will be spotty this week. As a temporary fix, you could use a different mode (I recorded prefork) or un-merge that PR. Of course this may be the least of your problems.

--
*** DoubleCheck identified this as CLEAN. Give feedback:
*** This is SPAM: http://filter.emailportal.com
*** More options: http://filter.emailportal.com

Jared Johnson

unread,

Jan 4, 2015, 2:00:02 AM1/4/15

to salv...@gmx.ch, qps...@perl.org

I'm about 51% sure that this will fix it, but I can't arrange a quick test just now because apparently xinetd is gone from os x mavericks. If you feel like testing this I would be interested in your results:

index 3675829..141214c 100755

--- a/qpsmtpd

+++ b/qpsmtpd

@@ -17,8 +17,8 @@ delete $ENV{ENV};

$ENV{PATH} = '/bin:/usr/bin:/var/qmail/bin';

my $qpsmtpd = Qpsmtpd::TcpServer->new();

-$SIG{__WARN__} = sub { $qpsmtpd->warn_handler(@_) };

$qpsmtpd->load_plugins();

+$SIG{__WARN__} = sub { $qpsmtpd->warn_handler(@_) };

$qpsmtpd->start_connection();

$qpsmtpd->run(\*STDIN); # pass the "socket" like -prefork/-forkserver

$qpsmtpd->run_hooks("post-connection");

Master has #168 reverted so that will probably work for you now as well, but if the above change works I can re-submit this PR in a working state.

-Jared

From: Jared Johnson <jjoh...@efolder.net>
Sent: Saturday, January 3, 2015 11:11 PM
To: salv...@gmx.ch
Cc: qps...@perl.org
Subject: Re: Issues in the current HEAD

Hans Salvisberg

unread,

Jan 4, 2015, 5:15:05 PM1/4/15

to Jared Johnson, qps...@perl.org

No, I don't think this has made any difference.

This is the error output written for an outgoing mail, i.e. submitted by an authorized user, after applying the patch:

...

4358 4358 click, disconnecting

4358 4358 (post-connection) connection_time: 1.528 s.

4358 FATAL PLUGIN ERROR [logging::file_3a0]: Can't call method "hook_logging" on unblessed reference at lib/Qpsmtpd/Plugin.pm line 47 during global destruction.

FATAL PLUGIN ERROR [logging::file_3a0]: Can't call method "hook_logging" on unblessed reference at lib/Qpsmtpd/Plugin.pm line 47 during global destruction.
FATAL PLUGIN ERROR [logging::file_3a1]: Can't call method "hook_logging" on unblessed reference at lib/Qpsmtpd/Plugin.pm line 47 during global destruction.
FATAL PLUGIN ERROR [logging::file_3a2]: Can't call method "hook_logging" on unblessed reference at lib/Qpsmtpd/Plugin.pm line 47 during global destruction.
FATAL PLUGIN ERROR [logging::file_3a3]: Can't call method "hook_logging" on unblessed reference at lib/Qpsmtpd/Plugin.pm line 47 during global destruction.
FATAL PLUGIN ERROR [logging::file_3a7]: Can't call method "hook_logging" on unblessed reference at lib/Qpsmtpd/Plugin.pm line 47 during global destruction.

If we call the block above

0 0 1 2 3 7

then it's followed by

1 0 1 2 3 7

2 0 1 2 3 7

3 0 1 2 3 7

7 0 1 2 3 7

and finally

Can't call method "warn_handler" on an undefined value at /home/smtpd/qpsmtpd/qpsmtpd line 21 during global destruction.

Gesendet: Sonntag, 04. Januar 2015 um 07:46 Uhr

Von: "Jared Johnson" <jjoh...@efolder.net>
An: "salv...@gmx.ch" <salv...@gmx.ch>

Cc: "qps...@perl.org" <qps...@perl.org>

Hans Salvisberg

unread,

Jan 4, 2015, 6:45:02 PM1/4/15

to Matt Simerson, qps...@perl.org

Hmm...

on https://github.com/smtpd/qpsmtpd/wiki/Install.Authentication suggests that you set up authentication without tls (it's commented out in config.sample) and only activate tls in a third step. Only the third page says

"Notice now that the previous authentication mechanisms are gone! When SSL is enabled, authentication is not advertised unless the connection is secure. This is a VERY good default, but it can be changed by editing config/tls_before_auth."

So, "AUTH" should be there as long as you don't have tls.

At the risk of beating a dead horse,

5c8f6b6 - Merge pull request #181 from jaredj/more-data-respond-tests (2015-01-01 18:59:21 -0800)

would stall after...

4729 4729 Loaded logging/warn 6

4729 4729 Connection from ###

4729 4729 (connect) earlytalker: pass, not spontaneous

4729 4729 (connect) relay: skip, no match

4729 4729 (connect) dnsbl: karma -1 (-2)

4729 4729 (connect) dnsbl: fail, NAUGHTY, zen.spamhaus.org

4729 4729 220 ### ESMTP qpsmtpd 0.95/v0.94-310-g5c8f6b6 ready; send us your mail, but not your spam.

4729 4729 dispatching EHLO [192.168.123.13]

4729 4729 250-### Hi ###

4729 4729 250-PIPELINING

4729 4729 250-8BITMIME

... and then time out later with...

4729 FATAL PLUGIN ERROR [logging::file_3a7]: Can't call method "notes" on unblessed reference at /home/smtpd/qpsmtpd/plugins/logging/file line 275, <STDIN> line 1.

4729 4729 (post-connection) connection_time: 101.698 s.

Note the missing "STARTTLS" above. Maybe it wasn't specifically "AUTH" missing but just the last option ("AUTH" if no tls, "STARTTLS" if with tls).

The new current HEAD

3db87b8 - Merge pull request #188 from msimerson/dbm-default-perm (2015-01-04 14:40:38 -0600)

does not have this problem anymore, both with the same config!

So I'm on HEAD/3db87b8 now.

Hans

Gesendet: Sonntag, 04. Januar 2015 um 06:44 Uhr
Von: "Matt Simerson" <ma...@tnpi.net>
An: salv...@gmx.ch
Cc: qps...@perl.org

Betreff: Re: Issues in the current HEAD

> On Jan 3, 2015, at 7:17 AM, salv...@gmx.ch wrote:
>
> Hi,
>
> I'm a long-time happy user of qpsmtpd with a small site, and right now I'm in the process of setting up my site on a new server and reinstalling qpsmtpd. I want to use auth_imap, which is in HEAD but not in 0.94, so I decided to try HEAD, but HEAD is broken: it does not announce "AUTH" at all. So I went for commit ee01a07 (2014-12-22 15:01:12 -0800), except for the following issue:

That's a feature. By default, QP only advertises AUTH if there's an AUTH provider AND the connection is secured. See the contents of config/tls_before_auth

Matt

Hans Salvisberg

unread,

Jan 4, 2015, 6:45:02 PM1/4/15

to Jared Johnson, qps...@perl.org

Going to the new HEAD

b1abc66 - qpsmtpd: Add additional dependency for geoip: Math::Complex. (2015-01-03 18:29:08 +0100)

has brought some relief:

Handle 2 now gives me only 7 instances of

FATAL PLUGIN ERROR [logging::file_3a7]: Can't call method "notes" on unblessed reference at /home/smtpd/qpsmtpd/plugins/logging/file line 275.

anymore, even though I still have 4 file loggers enabled. Plus one

5014 XX: Can't call method "notes" on unblessed reference at /home/smtpd/qpsmtpd/plugins/logging/file line 275.

And the warn_handler message is indeed gone, at least in my test case! Thanks!

Hans

Gesendet: Sonntag, 04. Januar 2015 um 06:11 Uhr

Von: "Jared Johnson" <jjoh...@efolder.net>
An: "salv...@gmx.ch" <salv...@gmx.ch>

Cc: "qps...@perl.org" <qps...@perl.org>

Betreff: Re: Issues in the current HEAD

Hans Salvisberg

unread,

Jan 5, 2015, 8:00:06 AM1/5/15

to Matt Simerson, Jared Johnson, qps...@perl.org

No, this produces

Deep recursion on subroutine "Qpsmtpd::Transaction::DESTROY" at lib/Qpsmtpd.pm line 271.
Deep recursion on subroutine "Qpsmtpd::log" at lib/Qpsmtpd/Transaction.pm line 242.
Deep recursion on subroutine "Qpsmtpd::varlog" at lib/Qpsmtpd.pm line 93.
Deep recursion on subroutine "Qpsmtpd::run_hooks_no_respond" at lib/Qpsmtpd.pm line 105.
Out of memory!

Hans

Gesendet: Montag, 05. Januar 2015 um 01:35 Uhr
Von: "Matt Simerson" <ma...@tnpi.net>
An: "Hans Salvisberg" <salv...@gmx.ch>
Cc: "Jared Johnson" <jjoh...@efolder.net>, "qps...@perl.org" <qps...@perl.org>

Betreff: Re: Issues in the current HEAD

On Jan 4, 2015, at 3:38 PM, Hans Salvisberg <salv...@gmx.ch> wrote:

Going to the new HEAD

b1abc66 - qpsmtpd: Add additional dependency for geoip: Math::Complex. (2015-01-03 18:29:08 +0100)

has brought some relief:

Handle 2 now gives me only 7 instances of

FATAL PLUGIN ERROR [logging::file_3a7]: Can't call method "notes" on unblessed reference at /home/smtpd/qpsmtpd/plugins/logging/file line 275.

anymore, even though I still have 4 file loggers enabled. Plus one

5014 XX: Can't call method "notes" on unblessed reference at /home/smtpd/qpsmtpd/plugins/logging/file line 275.

And the warn_handler message is indeed gone, at least in my test case! Thanks!

Hans

Seems to be a bug in that logging plugin:

if ( !$self->{_f}

|| !$self->{_nosplit}

|| !$transaction

|| !$transaction->notes('file-logged-this-session'))

The last line is 275, and apparently $transaction isn't a reference there. $transaction can be an empty hash defined in ::Qpsmtpd, which seems like a dumb default, as it will cause arrow operations like this one to blow up). Try this and see if it helps:

--- a/lib/Qpsmtpd.pm

+++ b/lib/Qpsmtpd.pm

@@ -244,7 +244,10 @@ sub _load_package_plugin {

return $plug;

}

-sub transaction { return {}; } # base class implements empty transaction

+sub transaction {

+ eval 'use Qpsmtpd::Transaction';

+ return Qpsmtpd::Transaction->new();

+}

sub run_hooks {

my ($self, $hook) = (shift, shift);

Matt