On 2007-08-30 13:55:08 -0400, Guy Hulbert wrote: > On Thu, 2007-08-30 at 13:53 -0400, Guy Hulbert wrote: > > On Fri, 2007-08-31 at 00:59 +0800, Ask Bjørn Hansen wrote: > > > Woah - bikeshedding galore! > > > > > > I just got my email downloaded to my mac (I'm traveling) and Mail.app > > > says there are 61 mails in this thread (plus those I deleted > > > earlier!?!). > > > > > > Enough already. > > > > There might have been a little less chat if he'd posted the code to the > > list ... fwiw, here it is. > > > > > > > > If anyone has a serious realistic concern with what Matt did, please > > > > http://svn.perl.org/qpsmtpd/trunk/lib/Qpsmtpd/Transaction.pm > > > > Sorry, I missed this bit: > > my $SALT_HOST => crypt(hostname, chr(65+rand(57)).chr(65+rand(57))); ^^ And Matt apparently missed this ;-).
> $SALT_HOST =~ tr/A-Za-z0-9//cd;
>
>
> > # Generate unique id
> > # use gettimeofday for microsec precision
> > # add in rand() in case gettimeofday clock is slow (e.g. bsd?)
> > # add in $$ in case srand is set per process
> > my ($start, $mstart) = gettimeofday();
> > my $id = sprintf("%d.%06d.%s.%d.%d",
> > $start,
> > $mstart,
> > $SALT_HOST,
> > rand(10000),
> > $$,
> > );
Anyway, I do have serious realistic concerns with that. To demonstrate
them I modified loggin/warn slightly:
--- plugins/logging/warn 2007-08-30 21:16:13.000000000 +0200
+++ plugins/logging/transaction_id 2007-08-30 20:51:41.000000000 +0200
@@ -31,7 +31,7 @@
return DECLINED if defined $plugin and $plugin eq $self->plugin_name;
warn
- join(" ", $$ .
+ join(" ", ($transaction ? $transaction->id : "???") .
(defined $plugin ? " $plugin plugin:" :
defined $hook ? " running plugin ($hook):" : ""),
@log), "\n"
And here is some sample output (at level LOGINFO):
1 1188500891.616465.eUqA14oEas5n2.2440.24861 Loaded
Qpsmtpd::Plugin::logging::transaction_id=HASH(0x87d2c00)
2 1188500891.616465.eUqA14oEas5n2.2440.24861 Listening on 0.0.0.0:2525
3 1188500891.616465.eUqA14oEas5n2.2440.24861 Running as user hjp, group
hjp
4 1188500891.616465.eUqA14oEas5n2.2440.24861 Initializing spool_dir
5 1188500891.616465.eUqA14oEas5n2.2440.24861 Permissions on spool_dir
/home/hjp/tmp/ are not 0700
6 1188500891.616465.eUqA14oEas5n2.2440.24861 size_threshold set to 0
7 1188500891.616465.eUqA14oEas5n2.2440.24861 Accepted connection 0/15
from 127.0.0.1 / localhost
8 1188500891.616465.eUqA14oEas5n2.2440.24861 Connection from localhost
[127.0.0.1]
9 1188500891.616465.eUqA14oEas5n2.2440.24861 check_earlytalker plugin:
remote host said nothing spontaneous, proceeding
10 1188500891.616465.eUqA14oEas5n2.2440.24861 220 hrunkner ESMTP qpsmtpd
0.40 ready; send us your mail, but not your spam.
11 1188500891.616465.eUqA14oEas5n2.2440.24861 dispatching ehlo foo
12 1188500891.616465.eUqA14oEas5n2.2440.24861 250-hrunkner Hi localhost
[127.0.0.1]
13 1188500891.616465.eUqA14oEas5n2.2440.24861 250-PIPELINING
14 1188500891.616465.eUqA14oEas5n2.2440.24861 250-8BITMIME
15 1188500891.616465.eUqA14oEas5n2.2440.24861 250 AUTH PLAIN LOGIN CRAM-MD5
16 1188500891.616465.eUqA14oEas5n2.2440.24861 dispatching mail from:<>
17 1188500925.148306.eUqA14oEas5n2.6284.24865 full from_parameter: from:<>
The transaction id changes here (as it should), but how are we to know
that line 17 belongs to the same connection as line 16? Here there is
only one parallel connection (I am awful as speaking SMTP in parallel
:-), but if there are several it could happen that the "dispatching
mail" and "full from_parameter" lines of multiple connections are
interleaved. Then you lose the information about the client.
18 1188500925.148306.eUqA14oEas5n2.6284.24865 from email address : [<>]
19 1188500925.148306.eUqA14oEas5n2.6284.24865 getting mail from <>
20 1188500925.148306.eUqA14oEas5n2.6284.24865 250 <>, sender OK - how
exciting to get mail from you!
21 1188500925.148306.eUqA14oEas5n2.6284.24865 dispatching rcpt to:<bla>
22 1188500925.148306.eUqA14oEas5n2.6284.24865 to email address : [<bla>]
23 1188500925.148306.eUqA14oEas5n2.6284.24865 501 could not parse recipient
24 1188500925.148306.eUqA14oEas5n2.6284.24865 dispatching rset
25 1188500939.224301.eUqA14oEas5n2.2814.24865 250 OK
Similar to the above. The transaction id changes. Here the process id
stays the same because I'm using forkserver, but with -async all
connections use the same pid, so that doesn't help.
26 1188500939.224301.eUqA14oEas5n2.2814.24865 dispatching mail
from:<[EMAIL PROTECTED]>
27 1188500988.137621.eUqA14oEas5n2.4740.24865 full from_parameter:
from:<[EMAIL PROTECTED]>
28 1188500988.137621.eUqA14oEas5n2.4740.24865 from email address :
[<[EMAIL PROTECTED]>]
29 1188500988.137621.eUqA14oEas5n2.4740.24865 getting mail from <[EMAIL
PROTECTED]>
30 1188500988.137621.eUqA14oEas5n2.4740.24865 250 <[EMAIL PROTECTED]>,
sender OK - how exciting to get mail from you!
31 1188500988.137621.eUqA14oEas5n2.4740.24865 dispatching rcpt to:<[EMAIL
PROTECTED]>
32 1188500988.137621.eUqA14oEas5n2.4740.24865 to email address : [<[EMAIL
PROTECTED]>]
33 1188500988.137621.eUqA14oEas5n2.4740.24865 550 Relaying denied (#5.7.1)
34 1188500988.137621.eUqA14oEas5n2.4740.24865 dispatching quit
35 1188500988.137621.eUqA14oEas5n2.4740.24865 221 hrunkner closing
connection. Have a wonderful day.
36 1188500988.137621.eUqA14oEas5n2.4740.24865 click, disconnecting
37 1188500891.616465.eUqA14oEas5n2.2440.24861 cleaning up after 24865
Ok, we're back in the parent now and using the same transaction id
again.
38 1188500891.616465.eUqA14oEas5n2.2440.24861 Accepted connection 0/15
from 127.0.0.1 / localhost
39 1188500891.616465.eUqA14oEas5n2.2440.24861 Connection from localhost
[127.0.0.1]
40 1188500891.616465.eUqA14oEas5n2.2440.24861 check_earlytalker plugin:
remote host said nothing spontaneous, proceeding
And here we've accepted the next connection and forked and the
transaction id is still the same - so the beginnings of each connection
(up to the first MAIL command) cannot be distinguished.
41 1188500891.616465.eUqA14oEas5n2.2440.24861 220 hrunkner ESMTP qpsmtpd
0.40 ready; send us your mail, but not your spam.
42 1188500891.616465.eUqA14oEas5n2.2440.24861 dispatching ehlo foo
43 1188500891.616465.eUqA14oEas5n2.2440.24861 250-hrunkner Hi localhost
[127.0.0.1]
44 1188500891.616465.eUqA14oEas5n2.2440.24861 250-PIPELINING
45 1188500891.616465.eUqA14oEas5n2.2440.24861 250-8BITMIME
46 1188500891.616465.eUqA14oEas5n2.2440.24861 250 AUTH PLAIN LOGIN CRAM-MD5
47 1188500891.616465.eUqA14oEas5n2.2440.24861 dispatching mail
from:<[EMAIL PROTECTED]>
48 1188501079.319659.eUqA14oEas5n2.83.24915 full from_parameter:
from:<[EMAIL PROTECTED]>
49 1188501079.319659.eUqA14oEas5n2.83.24915 from email address : [<[EMAIL
PROTECTED]>]
50 1188501079.319659.eUqA14oEas5n2.83.24915 getting mail from <[EMAIL
PROTECTED]>
51 1188501079.319659.eUqA14oEas5n2.83.24915 250 <[EMAIL PROTECTED]>,
sender OK - how exciting to get mail from you!
52 1188501079.319659.eUqA14oEas5n2.83.24915 dispatching rset
53 1188501082.198193.eUqA14oEas5n2.7497.24915 250 OK
54 1188501082.198193.eUqA14oEas5n2.7497.24915 dispatching quit
55 1188501082.198193.eUqA14oEas5n2.7497.24915 221 hrunkner closing
connection. Have a wonderful day.
56 1188501082.198193.eUqA14oEas5n2.7497.24915 click, disconnecting
57 1188500891.616465.eUqA14oEas5n2.2440.24861 cleaning up after 24915
As I wrote before I consider a connection id more important than a
transaction id: If I have a connection, I can always split it into
transactions with a bit of SMTP knowledge. But if I have only
transactions, I cannot reassemble them back into connections, so
information which is only recorded once per connection (like the client
address or EHLO parameter) is lost.
Unfortunately a similar patch to Qpsmtpd::Connection doesn't work with
forkserver, because it just reuses the same connection object over and
over (all changes are done after the fork, so the parent always has a
"pristine" connection. But we can just reinitialize the id before the
pre_connection hook.
Then a similar session to the one above looks like this:
1 1188504537.392238.w16URlX9gyk.6628.26545 Loaded
Qpsmtpd::Plugin::logging::connection_id=HASH(0x87d38dc)
2 1188504537.392238.w16URlX9gyk.6628.26545 Listening on 0.0.0.0:2525
3 1188504537.392238.w16URlX9gyk.6628.26545 Running as user hjp, group hjp
4 1188504537.392238.w16URlX9gyk.6628.26545 Initializing spool_dir
5 1188504537.392238.w16URlX9gyk.6628.26545 Permissions on spool_dir
/home/hjp/tmp/ are not 0700
6 1188504537.392238.w16URlX9gyk.6628.26545 size_threshold set to 0
7 1188504546.152131.w16URlX9gyk.7327.26545 Accepted connection 0/15 from
127.0.0.1 / localhost
We have accepted a new connection and it has a new id.
8 1188504546.152131.w16URlX9gyk.7327.26545 Connection from localhost
[127.0.0.1]
9 1188504546.152131.w16URlX9gyk.7327.26545 check_earlytalker plugin:
remote host said nothing spontaneous, proceeding
10 1188504546.152131.w16URlX9gyk.7327.26545 220 hrunkner ESMTP qpsmtpd
0.40 ready; send us your mail, but not your spam.
11 1188504546.152131.w16URlX9gyk.7327.26545 dispatching ehlo localhost
12 1188504546.152131.w16URlX9gyk.7327.26545 250-hrunkner Hi localhost
[127.0.0.1]
13 1188504546.152131.w16URlX9gyk.7327.26545 250-PIPELINING
14 1188504546.152131.w16URlX9gyk.7327.26545 250-8BITMIME
15 1188504546.152131.w16URlX9gyk.7327.26545 250 AUTH PLAIN LOGIN CRAM-MD5
16 1188504546.152131.w16URlX9gyk.7327.26545 dispatching mail from:<>
17 1188504546.152131.w16URlX9gyk.7327.26545 full from_parameter: from:<>
We have received a mail from: command, it it was in the connecion from
localhost [127.0.0.1].
18 1188504546.152131.w16URlX9gyk.7327.26545 from email address : [<>]
19 1188504546.152131.w16URlX9gyk.7327.26545 getting mail from <>
20 1188504546.152131.w16URlX9gyk.7327.26545 250 <>, sender OK - how
exciting to get mail from you!
21 1188504546.152131.w16URlX9gyk.7327.26545 dispatching rset
Still the same connection.
22 1188504546.152131.w16URlX9gyk.7327.26545 250 OK
23 1188504546.152131.w16URlX9gyk.7327.26545 dispatching mail from:<[EMAIL
PROTECTED]>
24 1188504546.152131.w16URlX9gyk.7327.26545 full from_parameter:
from:<[EMAIL PROTECTED]>
25 1188504546.152131.w16URlX9gyk.7327.26545 from email address : [<[EMAIL
PROTECTED]>]
26 1188504546.152131.w16URlX9gyk.7327.26545 getting mail from <[EMAIL
PROTECTED]>
27 1188504546.152131.w16URlX9gyk.7327.26545 250 <[EMAIL PROTECTED]>,
sender OK - how exciting to get mail from you!
28 1188504546.152131.w16URlX9gyk.7327.26545 dispatching quit
29 1188504546.152131.w16URlX9gyk.7327.26545 221 hrunkner closing
connection. Have a wonderful day.
30 1188504546.152131.w16URlX9gyk.7327.26545 click, disconnecting
The end of the first connection.
31 1188504546.152131.w16URlX9gyk.7327.26545 cleaning up after 26551
Back in the parent. Still using the old connection id, but that single
message can be easily ignored.
32 1188504596.595799.w16URlX9gyk.4468.26545 Accepted connection 0/15 from
127.0.0.1 / localhost
A new connection with a new id.
33 1188504596.595799.w16URlX9gyk.4468.26545 Connection from localhost
[127.0.0.1]
34 1188504596.595799.w16URlX9gyk.4468.26545 check_earlytalker plugin:
remote host said nothing spontaneous, proceeding
35 1188504596.595799.w16URlX9gyk.4468.26545 220 hrunkner ESMTP qpsmtpd
0.40 ready; send us your mail, but not your spam.
36 1188504596.595799.w16URlX9gyk.4468.26545 dispatching ehlo localhost
37 1188504596.595799.w16URlX9gyk.4468.26545 250-hrunkner Hi localhost
[127.0.0.1]
38 1188504596.595799.w16URlX9gyk.4468.26545 250-PIPELINING
39 1188504596.595799.w16URlX9gyk.4468.26545 250-8BITMIME
40 1188504596.595799.w16URlX9gyk.4468.26545 250 AUTH PLAIN LOGIN CRAM-MD5
41 1188504596.595799.w16URlX9gyk.4468.26545 dispatching mail from:<[EMAIL
PROTECTED]>
42 1188504596.595799.w16URlX9gyk.4468.26545 full from_parameter:
from:<[EMAIL PROTECTED]>
43 1188504596.595799.w16URlX9gyk.4468.26545 from email address : [<[EMAIL
PROTECTED]>]
44 1188504596.595799.w16URlX9gyk.4468.26545 getting mail from <[EMAIL
PROTECTED]>
45 1188504596.595799.w16URlX9gyk.4468.26545 250 <[EMAIL PROTECTED]>,
sender OK - how exciting to get mail from you!
46 1188504596.595799.w16URlX9gyk.4468.26545 dispatching quit
47 1188504596.595799.w16URlX9gyk.4468.26545 221 hrunkner closing
connection. Have a wonderful day.
48 1188504596.595799.w16URlX9gyk.4468.26545 click, disconnecting
49 1188504596.595799.w16URlX9gyk.4468.26545 cleaning up after 26572
I haven't tested it with anything but forkserver, but I checked it in on
trunk so others can play with it.
I think it should be possible to derive the transaction id from the
connection id, but I see no way to get from a transaction object to the
underlying connection object. Am I blind?
hp
--
_ | Peter J. Holzer | I know I'd be respectful of a pirate
|_|_) | Sysadmin WSR | with an emu on his shoulder.
| | | [EMAIL PROTECTED] |
__/ | http://www.hjp.at/ | -- Sam in "Freefall"
signature.asc
Description: Digital signature
