Skip to content

Commit 14b5156

Browse files
marcbradshawmarcbradshaw
committed
Core: Add timing data to logs
Refactor timing metrics such that a timeout does not lose data
1 parent bc6fdcb commit 14b5156

File tree

1 file changed

+109
-41
lines changed

1 file changed

+109
-41
lines changed

‎lib/Mail/Milter/Authentication/Handler.pm‎

Lines changed: 109 additions & 41 deletions
Original file line numberDiff line numberDiff line change
@@ -240,6 +240,52 @@ sub register_metrics {
240240
};
241241
}
242242

243+
=metric_method I<record_time_taken($callback, $handler, $microseconds)>
244+
245+
Record the time taken in a particular callback/handler
246+
247+
=cut
248+
249+
sub record_time_taken($self, $callback, $handler, $microseconds) {
250+
$self->metric_count('time_microseconds_total', { 'callback' => $callback, 'handler' => $handler }, $microseconds);
251+
252+
# For extended logging
253+
254+
# setup/dequeue stages are not relevant and abort/close occur post extended logging
255+
return if $callback eq 'setup'
256+
|| $callback eq 'dequeue'
257+
|| $callback eq 'abort'
258+
|| $callback eq 'close';
259+
260+
my $label = join('.', $callback, $handler);
261+
262+
# connect and helo stages go into c_timing (connection persist)
263+
if ($callback eq 'connect' || $callback eq 'helo') {
264+
$self->{c_timing} = {} unless $self->{c_timing};
265+
$self->{c_timing}->{$label} = 0 unless $self->{c_timing}->{$label};
266+
$self->{c_timing}->{$label} = $self->{c_timing}->{$label} + $microseconds;
267+
} else {
268+
# remaining are envfrom rcptto header eoh body and eom addheader stages which are
269+
# email specific and go into timing
270+
$self->{timing} = {} unless $self->{timing};
271+
$self->{timing}->{$label} = 0 unless $self->{timing}->{$label};
272+
$self->{timing}->{$label} = $self->{timing}->{$label} + $microseconds;
273+
}
274+
}
275+
276+
=metric_method I<get_timing_data()>
277+
278+
Return timing data for this transaction
279+
280+
=cut
281+
282+
sub get_timing_data($self) {
283+
my $c_timing = $self->{c_timing} // {};
284+
my $timing = $self->{timing} // {};
285+
my %data = ( %$c_timing, %$timing );
286+
return \%data;
287+
}
288+
243289
=callback_method I<top_dequeue_callback()>
244290
245291
Top level handler for dequeue.
@@ -259,12 +305,15 @@ sub top_dequeue_callback {
259305
$self->set_alarm( $timeout );
260306
}
261307
my $callbacks = $self->get_callbacks( 'dequeue' );
308+
262309
foreach my $handler ( @$callbacks ) {
263310
$self->dbgout( 'CALLBACK', 'Dequeue ' . $handler, LOG_DEBUG );
264311
my $start_time = $self->get_microseconds();
265-
$self->get_handler($handler)->dequeue_callback();
312+
eval{ $self->get_handler($handler)->dequeue_callback(); };
313+
my $error = $@;
266314
$self->dbgoutwrite();
267-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'dequeue', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
315+
$self->record_time_taken('dequeue', $handler, $self->get_microseconds_since($start_time));
316+
die $error if $error;
268317
}
269318
$self->set_alarm(0);
270319
};
@@ -297,8 +346,11 @@ sub top_setup_callback {
297346
foreach my $handler ( @$callbacks ) {
298347
$self->dbgout( 'CALLBACK', 'Setup ' . $handler, LOG_DEBUG );
299348
my $start_time = $self->get_microseconds();
300-
$self->get_handler($handler)->setup_callback();
301-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'setup', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
349+
eval{ $self->get_handler($handler)->setup_callback(); };
350+
my $error = $@;
351+
$self->record_time_taken('setup', $handler, $self->get_microseconds_since($start_time));
352+
die $error if $error;
353+
#$self->metric_count( 'time_microseconds_total', { 'callback' => 'setup', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
302354
}
303355
$self->status('postsetup');
304356
}
@@ -630,13 +682,14 @@ sub top_connect_callback {
630682
$self->dbgout( 'CALLBACK', 'Connect ' . $handler, LOG_DEBUG );
631683
my $start_time = $self->get_microseconds();
632684
eval{ $self->get_handler($handler)->connect_callback( $hostname, $ip ); };
633-
if ( my $error = $@ ) {
685+
my $error = $@;
686+
$self->record_time_taken('connect', $handler, $self->get_microseconds_since($start_time));
687+
if ($error) {
688+
$self->metric_count( 'callback_error_total', { 'stage' => 'connect', 'handler' => $handler } );
634689
$self->handle_exception( $error );
635690
$self->exit_on_close( 'Connect callback error ' . $error );
636691
$self->tempfail_on_error();
637-
$self->metric_count( 'callback_error_total', { 'stage' => 'connect', 'handler' => $handler } );
638692
}
639-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'connect', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
640693
$self->check_timeout();
641694
}
642695
$self->set_alarm(0);
@@ -713,13 +766,14 @@ sub top_helo_callback {
713766
$self->dbgout( 'CALLBACK', 'Helo ' . $handler, LOG_DEBUG );
714767
my $start_time = $self->get_microseconds();
715768
eval{ $self->get_handler($handler)->helo_callback($helo_host); };
716-
if ( my $error = $@ ) {
769+
my $error = $@;
770+
$self->record_time_taken('helo', $handler, $self->get_microseconds_since($start_time));
771+
if ($error) {
772+
$self->metric_count( 'callback_error_total', { 'stage' => 'helo', 'handler' => $handler } );
717773
$self->handle_exception( $error );
718774
$self->exit_on_close( 'HELO callback error ' . $error );
719775
$self->tempfail_on_error();
720-
$self->metric_count( 'callback_error_total', { 'stage' => 'helo', 'handler' => $handler } );
721776
}
722-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'helo', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
723777
$self->check_timeout();
724778
}
725779
}
@@ -771,19 +825,21 @@ sub top_envfrom_callback {
771825
delete $self->{'pre_headers'};
772826
delete $self->{'add_headers'};
773827
delete $self->{'suppress_error_emails'};
828+
delete $self->{'timing'};
774829

775830
my $callbacks = $self->get_callbacks( 'envfrom' );
776831
foreach my $handler ( @$callbacks ) {
777832
$self->dbgout( 'CALLBACK', 'EnvFrom ' . $handler, LOG_DEBUG );
778833
my $start_time = $self->get_microseconds();
779834
eval { $self->get_handler($handler)->envfrom_callback($env_from, @params); };
780-
if ( my $error = $@ ) {
835+
my $error = $@;
836+
$self->record_time_taken('envfrom', $handler, $self->get_microseconds_since($start_time));
837+
if ($error) {
838+
$self->metric_count( 'callback_error_total', { 'stage' => 'envfrom', 'handler' => $handler } );
781839
$self->handle_exception( $error );
782840
$self->exit_on_close( 'Env From callback error ' . $error );
783841
$self->tempfail_on_error();
784-
$self->metric_count( 'callback_error_total', { 'stage' => 'envfrom', 'handler' => $handler } );
785842
}
786-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'envfrom', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
787843
$self->check_timeout();
788844
}
789845
$self->set_alarm(0);
@@ -830,13 +886,14 @@ sub top_envrcpt_callback {
830886
$self->dbgout( 'CALLBACK', 'EnvRcpt ' . $handler, LOG_DEBUG );
831887
my $start_time = $self->get_microseconds();
832888
eval{ $self->get_handler($handler)->envrcpt_callback($env_to, @params); };
833-
if ( my $error = $@ ) {
889+
my $error = $@;
890+
$self->record_time_taken('rcptto', $handler, $self->get_microseconds_since($start_time));
891+
if ($error) {
892+
$self->metric_count( 'callback_error_total', { 'stage' => 'rcptto', 'handler' => $handler } );
834893
$self->handle_exception( $error );
835894
$self->exit_on_close( 'Env Rcpt callback error ' . $error );
836895
$self->tempfail_on_error();
837-
$self->metric_count( 'callback_error_total', { 'stage' => 'rcptto', 'handler' => $handler } );
838896
}
839-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'rcptto', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
840897
$self->check_timeout();
841898
}
842899
$self->set_alarm(0);
@@ -890,13 +947,14 @@ sub top_header_callback {
890947
$self->dbgout( 'CALLBACK', 'Header ' . $handler, LOG_DEBUG );
891948
my $start_time = $self->get_microseconds();
892949
eval{ $self->get_handler($handler)->header_callback( $header, $value, $original ); };
893-
if ( my $error = $@ ) {
950+
my $error = $@;
951+
$self->record_time_taken('header', $handler, $self->get_microseconds_since($start_time));
952+
if ($error) {
953+
$self->metric_count( 'callback_error_total', { 'stage' => 'header', 'handler' => $handler } );
894954
$self->handle_exception( $error );
895955
$self->exit_on_close( 'Header callback error ' . $error );
896956
$self->tempfail_on_error();
897-
$self->metric_count( 'callback_error_total', { 'stage' => 'header', 'handler' => $handler } );
898957
}
899-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'header', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
900958
$self->check_timeout();
901959
}
902960
$self->set_alarm(0);
@@ -941,13 +999,14 @@ sub top_eoh_callback {
941999
$self->dbgout( 'CALLBACK', 'EOH ' . $handler, LOG_DEBUG );
9421000
my $start_time = $self->get_microseconds();
9431001
eval{ $self->get_handler($handler)->eoh_callback(); };
944-
if ( my $error = $@ ) {
1002+
my $error = $@;
1003+
$self->record_time_taken('eoh', $handler, $self->get_microseconds_since($start_time));
1004+
if ($error) {
1005+
$self->metric_count( 'callback_error_total', { 'stage' => 'eoh', 'handler' => $handler } );
9451006
$self->handle_exception( $error );
9461007
$self->exit_on_close( 'EOH callback error ' . $error );
9471008
$self->tempfail_on_error();
948-
$self->metric_count( 'callback_error_total', { 'stage' => 'eoh', 'handler' => $handler } );
9491009
}
950-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'eoh', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
9511010
$self->check_timeout();
9521011
}
9531012
$self->set_alarm(0);
@@ -993,13 +1052,14 @@ sub top_body_callback {
9931052
$self->dbgout( 'CALLBACK', 'Body ' . $handler, LOG_DEBUG );
9941053
my $start_time = $self->get_microseconds();
9951054
eval{ $self->get_handler($handler)->body_callback( $body_chunk ); };
996-
if ( my $error = $@ ) {
1055+
my $error = $@;
1056+
$self->record_time_taken('body', $handler, $self->get_microseconds_since($start_time));
1057+
if ($error) {
1058+
$self->metric_count( 'callback_error_total', { 'stage' => 'body', 'handler' => $handler } );
9971059
$self->handle_exception( $error );
9981060
$self->exit_on_close( 'Body callback error ' . $error );
9991061
$self->tempfail_on_error();
1000-
$self->metric_count( 'callback_error_total', { 'stage' => 'body', 'handler' => $handler } );
10011062
}
1002-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'body', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
10031063
$self->check_timeout();
10041064
}
10051065
$self->set_alarm(0);
@@ -1045,13 +1105,14 @@ sub top_eom_callback {
10451105
$self->dbgout( 'CALLBACK', 'EOM ' . $handler, LOG_DEBUG );
10461106
my $start_time = $self->get_microseconds();
10471107
eval{ $self->get_handler($handler)->eom_callback(); };
1048-
if ( my $error = $@ ) {
1108+
my $error = $@;
1109+
$self->record_time_taken('eom', $handler, $self->get_microseconds_since($start_time));
1110+
if ($error) {
1111+
$self->metric_count( 'callback_error_total', { 'stage' => 'eom', 'handler' => $handler } );
10491112
$self->handle_exception( $error );
10501113
$self->exit_on_close( 'EOM callback error ' . $error );
10511114
$self->tempfail_on_error();
1052-
$self->metric_count( 'callback_error_total', { 'stage' => 'eom', 'handler' => $handler } );
10531115
}
1054-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'eom', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
10551116
$self->check_timeout();
10561117
}
10571118
$self->set_alarm(0);
@@ -1123,13 +1184,14 @@ sub top_abort_callback {
11231184
$self->dbgout( 'CALLBACK', 'Abort ' . $handler, LOG_DEBUG );
11241185
my $start_time = $self->get_microseconds();
11251186
eval{ $self->get_handler($handler)->abort_callback(); };
1126-
if ( my $error = $@ ) {
1187+
$self->record_time_taken('abort', $handler, $self->get_microseconds_since($start_time));
1188+
my $error = $@;
1189+
if ($error) {
1190+
$self->metric_count( 'callback_error_total', { 'stage' => 'abort', 'handler' => $handler } );
11271191
$self->handle_exception( $error );
11281192
$self->exit_on_close( 'Abort callback error ' . $error );
11291193
$self->tempfail_on_error();
1130-
$self->metric_count( 'callback_error_total', { 'stage' => 'abort', 'handler' => $handler } );
11311194
}
1132-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'abort', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
11331195
$self->check_timeout();
11341196
}
11351197
$self->set_alarm(0);
@@ -1177,13 +1239,14 @@ sub top_close_callback {
11771239
$self->dbgout( 'CALLBACK', 'Close ' . $handler, LOG_DEBUG );
11781240
my $start_time = $self->get_microseconds();
11791241
eval{ $self->get_handler($handler)->close_callback(); };
1180-
if ( my $error = $@ ) {
1242+
my $error = $@;
1243+
$self->record_time_taken('close', $handler, $self->get_microseconds_since($start_time));
1244+
if ($error) {
1245+
$self->metric_count( 'callback_error_total', { 'stage' => 'close', 'handler' => $handler } );
11811246
$self->handle_exception( $error );
11821247
$self->exit_on_close( 'Close callback error ' . $error );
11831248
$self->tempfail_on_error();
1184-
$self->metric_count( 'callback_error_total', { 'stage' => 'close', 'handler' => $handler } );
11851249
}
1186-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'close', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
11871250
$self->check_timeout();
11881251

11891252
my $handler_object = $self->get_handler($handler);
@@ -1210,6 +1273,8 @@ sub top_close_callback {
12101273
delete $self->{'raw_helo_name'};
12111274
delete $self->{'c_auth_headers'};
12121275
delete $self->{'auth_headers'};
1276+
delete $self->{'c_timing'};
1277+
delete $self->{'timing'};
12131278
delete $self->{'pre_headers'};
12141279
delete $self->{'add_headers'};
12151280
delete $self->{'ip_object'};
@@ -1241,8 +1306,10 @@ sub top_addheader_callback {
12411306
my $callbacks = $self->get_callbacks( 'addheader' );
12421307
foreach my $handler ( @$callbacks ) {
12431308
my $start_time = $self->get_microseconds();
1244-
$self->get_handler($handler)->addheader_callback($self);
1245-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'addheader', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
1309+
eval{ $self->get_handler($handler)->addheader_callback($self); };
1310+
my $error = $@;
1311+
$self->record_time_taken('addheader', $handler, $self->get_microseconds_since($start_time));
1312+
die $error if $error;
12461313
$self->check_timeout();
12471314
}
12481315
$self->set_alarm(0);
@@ -2582,17 +2649,18 @@ sub add_headers {
25822649
$self->add_auth_headers_of_type($type);
25832650
}
25842651

2585-
if ($config->{extended_log}) {
2586-
my $j = JSON->new->canonical->utf8;
2587-
$self->dbgout( 'ARex',$j->encode($self->{extended_log}), LOG_INFO );
2588-
}
2589-
25902652
if ( my $reason = $self->get_quarantine_mail() ) {
25912653
$self->prepend_header( 'X-Disposition-Quarantine', $reason );
25922654
}
25932655

25942656
$top_handler->top_addheader_callback();
25952657

2658+
$self->{extended_log}->{timing} = $self->get_timing_data;
2659+
if ($config->{extended_log}) {
2660+
my $j = JSON->new->canonical->utf8;
2661+
$self->dbgout( 'ARex',$j->encode($self->{extended_log}), LOG_INFO );
2662+
}
2663+
25962664
if ( exists( $top_handler->{'pre_headers'} ) ) {
25972665
foreach my $header ( @{ $top_handler->{'pre_headers'} } ) {
25982666
$self->dbgout( 'PreHeader',

0 commit comments

Comments
 (0)