Skip to content

Commit 5b41328

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 5b41328

File tree

2 files changed

+109
-41
lines changed

2 files changed

+109
-41
lines changed

‎Changes‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
Revision history for Mail-Milter-Authentication
22

33
{{$NEXT}}
4+
- Core: Add timing data to the extended logging
45

56
3.20230911 2023-09-11 06:18:44+00:00 UTC
67
- Core: Switch from deprecated method in Net::DNS

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

Lines changed: 108 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,10 @@ 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;
302353
}
303354
$self->status('postsetup');
304355
}
@@ -630,13 +681,14 @@ sub top_connect_callback {
630681
$self->dbgout( 'CALLBACK', 'Connect ' . $handler, LOG_DEBUG );
631682
my $start_time = $self->get_microseconds();
632683
eval{ $self->get_handler($handler)->connect_callback( $hostname, $ip ); };
633-
if ( my $error = $@ ) {
684+
my $error = $@;
685+
$self->record_time_taken('connect', $handler, $self->get_microseconds_since($start_time));
686+
if ($error) {
687+
$self->metric_count( 'callback_error_total', { 'stage' => 'connect', 'handler' => $handler } );
634688
$self->handle_exception( $error );
635689
$self->exit_on_close( 'Connect callback error ' . $error );
636690
$self->tempfail_on_error();
637-
$self->metric_count( 'callback_error_total', { 'stage' => 'connect', 'handler' => $handler } );
638691
}
639-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'connect', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
640692
$self->check_timeout();
641693
}
642694
$self->set_alarm(0);
@@ -713,13 +765,14 @@ sub top_helo_callback {
713765
$self->dbgout( 'CALLBACK', 'Helo ' . $handler, LOG_DEBUG );
714766
my $start_time = $self->get_microseconds();
715767
eval{ $self->get_handler($handler)->helo_callback($helo_host); };
716-
if ( my $error = $@ ) {
768+
my $error = $@;
769+
$self->record_time_taken('helo', $handler, $self->get_microseconds_since($start_time));
770+
if ($error) {
771+
$self->metric_count( 'callback_error_total', { 'stage' => 'helo', 'handler' => $handler } );
717772
$self->handle_exception( $error );
718773
$self->exit_on_close( 'HELO callback error ' . $error );
719774
$self->tempfail_on_error();
720-
$self->metric_count( 'callback_error_total', { 'stage' => 'helo', 'handler' => $handler } );
721775
}
722-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'helo', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
723776
$self->check_timeout();
724777
}
725778
}
@@ -771,19 +824,21 @@ sub top_envfrom_callback {
771824
delete $self->{'pre_headers'};
772825
delete $self->{'add_headers'};
773826
delete $self->{'suppress_error_emails'};
827+
delete $self->{'timing'};
774828

775829
my $callbacks = $self->get_callbacks( 'envfrom' );
776830
foreach my $handler ( @$callbacks ) {
777831
$self->dbgout( 'CALLBACK', 'EnvFrom ' . $handler, LOG_DEBUG );
778832
my $start_time = $self->get_microseconds();
779833
eval { $self->get_handler($handler)->envfrom_callback($env_from, @params); };
780-
if ( my $error = $@ ) {
834+
my $error = $@;
835+
$self->record_time_taken('envfrom', $handler, $self->get_microseconds_since($start_time));
836+
if ($error) {
837+
$self->metric_count( 'callback_error_total', { 'stage' => 'envfrom', 'handler' => $handler } );
781838
$self->handle_exception( $error );
782839
$self->exit_on_close( 'Env From callback error ' . $error );
783840
$self->tempfail_on_error();
784-
$self->metric_count( 'callback_error_total', { 'stage' => 'envfrom', 'handler' => $handler } );
785841
}
786-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'envfrom', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
787842
$self->check_timeout();
788843
}
789844
$self->set_alarm(0);
@@ -830,13 +885,14 @@ sub top_envrcpt_callback {
830885
$self->dbgout( 'CALLBACK', 'EnvRcpt ' . $handler, LOG_DEBUG );
831886
my $start_time = $self->get_microseconds();
832887
eval{ $self->get_handler($handler)->envrcpt_callback($env_to, @params); };
833-
if ( my $error = $@ ) {
888+
my $error = $@;
889+
$self->record_time_taken('rcptto', $handler, $self->get_microseconds_since($start_time));
890+
if ($error) {
891+
$self->metric_count( 'callback_error_total', { 'stage' => 'rcptto', 'handler' => $handler } );
834892
$self->handle_exception( $error );
835893
$self->exit_on_close( 'Env Rcpt callback error ' . $error );
836894
$self->tempfail_on_error();
837-
$self->metric_count( 'callback_error_total', { 'stage' => 'rcptto', 'handler' => $handler } );
838895
}
839-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'rcptto', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
840896
$self->check_timeout();
841897
}
842898
$self->set_alarm(0);
@@ -890,13 +946,14 @@ sub top_header_callback {
890946
$self->dbgout( 'CALLBACK', 'Header ' . $handler, LOG_DEBUG );
891947
my $start_time = $self->get_microseconds();
892948
eval{ $self->get_handler($handler)->header_callback( $header, $value, $original ); };
893-
if ( my $error = $@ ) {
949+
my $error = $@;
950+
$self->record_time_taken('header', $handler, $self->get_microseconds_since($start_time));
951+
if ($error) {
952+
$self->metric_count( 'callback_error_total', { 'stage' => 'header', 'handler' => $handler } );
894953
$self->handle_exception( $error );
895954
$self->exit_on_close( 'Header callback error ' . $error );
896955
$self->tempfail_on_error();
897-
$self->metric_count( 'callback_error_total', { 'stage' => 'header', 'handler' => $handler } );
898956
}
899-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'header', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
900957
$self->check_timeout();
901958
}
902959
$self->set_alarm(0);
@@ -941,13 +998,14 @@ sub top_eoh_callback {
941998
$self->dbgout( 'CALLBACK', 'EOH ' . $handler, LOG_DEBUG );
942999
my $start_time = $self->get_microseconds();
9431000
eval{ $self->get_handler($handler)->eoh_callback(); };
944-
if ( my $error = $@ ) {
1001+
my $error = $@;
1002+
$self->record_time_taken('eoh', $handler, $self->get_microseconds_since($start_time));
1003+
if ($error) {
1004+
$self->metric_count( 'callback_error_total', { 'stage' => 'eoh', 'handler' => $handler } );
9451005
$self->handle_exception( $error );
9461006
$self->exit_on_close( 'EOH callback error ' . $error );
9471007
$self->tempfail_on_error();
948-
$self->metric_count( 'callback_error_total', { 'stage' => 'eoh', 'handler' => $handler } );
9491008
}
950-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'eoh', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
9511009
$self->check_timeout();
9521010
}
9531011
$self->set_alarm(0);
@@ -993,13 +1051,14 @@ sub top_body_callback {
9931051
$self->dbgout( 'CALLBACK', 'Body ' . $handler, LOG_DEBUG );
9941052
my $start_time = $self->get_microseconds();
9951053
eval{ $self->get_handler($handler)->body_callback( $body_chunk ); };
996-
if ( my $error = $@ ) {
1054+
my $error = $@;
1055+
$self->record_time_taken('body', $handler, $self->get_microseconds_since($start_time));
1056+
if ($error) {
1057+
$self->metric_count( 'callback_error_total', { 'stage' => 'body', 'handler' => $handler } );
9971058
$self->handle_exception( $error );
9981059
$self->exit_on_close( 'Body callback error ' . $error );
9991060
$self->tempfail_on_error();
1000-
$self->metric_count( 'callback_error_total', { 'stage' => 'body', 'handler' => $handler } );
10011061
}
1002-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'body', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
10031062
$self->check_timeout();
10041063
}
10051064
$self->set_alarm(0);
@@ -1045,13 +1104,14 @@ sub top_eom_callback {
10451104
$self->dbgout( 'CALLBACK', 'EOM ' . $handler, LOG_DEBUG );
10461105
my $start_time = $self->get_microseconds();
10471106
eval{ $self->get_handler($handler)->eom_callback(); };
1048-
if ( my $error = $@ ) {
1107+
my $error = $@;
1108+
$self->record_time_taken('eom', $handler, $self->get_microseconds_since($start_time));
1109+
if ($error) {
1110+
$self->metric_count( 'callback_error_total', { 'stage' => 'eom', 'handler' => $handler } );
10491111
$self->handle_exception( $error );
10501112
$self->exit_on_close( 'EOM callback error ' . $error );
10511113
$self->tempfail_on_error();
1052-
$self->metric_count( 'callback_error_total', { 'stage' => 'eom', 'handler' => $handler } );
10531114
}
1054-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'eom', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
10551115
$self->check_timeout();
10561116
}
10571117
$self->set_alarm(0);
@@ -1123,13 +1183,14 @@ sub top_abort_callback {
11231183
$self->dbgout( 'CALLBACK', 'Abort ' . $handler, LOG_DEBUG );
11241184
my $start_time = $self->get_microseconds();
11251185
eval{ $self->get_handler($handler)->abort_callback(); };
1126-
if ( my $error = $@ ) {
1186+
$self->record_time_taken('abort', $handler, $self->get_microseconds_since($start_time));
1187+
my $error = $@;
1188+
if ($error) {
1189+
$self->metric_count( 'callback_error_total', { 'stage' => 'abort', 'handler' => $handler } );
11271190
$self->handle_exception( $error );
11281191
$self->exit_on_close( 'Abort callback error ' . $error );
11291192
$self->tempfail_on_error();
1130-
$self->metric_count( 'callback_error_total', { 'stage' => 'abort', 'handler' => $handler } );
11311193
}
1132-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'abort', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
11331194
$self->check_timeout();
11341195
}
11351196
$self->set_alarm(0);
@@ -1177,13 +1238,14 @@ sub top_close_callback {
11771238
$self->dbgout( 'CALLBACK', 'Close ' . $handler, LOG_DEBUG );
11781239
my $start_time = $self->get_microseconds();
11791240
eval{ $self->get_handler($handler)->close_callback(); };
1180-
if ( my $error = $@ ) {
1241+
my $error = $@;
1242+
$self->record_time_taken('close', $handler, $self->get_microseconds_since($start_time));
1243+
if ($error) {
1244+
$self->metric_count( 'callback_error_total', { 'stage' => 'close', 'handler' => $handler } );
11811245
$self->handle_exception( $error );
11821246
$self->exit_on_close( 'Close callback error ' . $error );
11831247
$self->tempfail_on_error();
1184-
$self->metric_count( 'callback_error_total', { 'stage' => 'close', 'handler' => $handler } );
11851248
}
1186-
$self->metric_count( 'time_microseconds_total', { 'callback' => 'close', 'handler' => $handler }, $self->get_microseconds_since( $start_time ) );
11871249
$self->check_timeout();
11881250

11891251
my $handler_object = $self->get_handler($handler);
@@ -1210,6 +1272,8 @@ sub top_close_callback {
12101272
delete $self->{'raw_helo_name'};
12111273
delete $self->{'c_auth_headers'};
12121274
delete $self->{'auth_headers'};
1275+
delete $self->{'c_timing'};
1276+
delete $self->{'timing'};
12131277
delete $self->{'pre_headers'};
12141278
delete $self->{'add_headers'};
12151279
delete $self->{'ip_object'};
@@ -1241,8 +1305,10 @@ sub top_addheader_callback {
12411305
my $callbacks = $self->get_callbacks( 'addheader' );
12421306
foreach my $handler ( @$callbacks ) {
12431307
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 ) );
1308+
eval{ $self->get_handler($handler)->addheader_callback($self); };
1309+
my $error = $@;
1310+
$self->record_time_taken('addheader', $handler, $self->get_microseconds_since($start_time));
1311+
die $error if $error;
12461312
$self->check_timeout();
12471313
}
12481314
$self->set_alarm(0);
@@ -2582,17 +2648,18 @@ sub add_headers {
25822648
$self->add_auth_headers_of_type($type);
25832649
}
25842650

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-
25902651
if ( my $reason = $self->get_quarantine_mail() ) {
25912652
$self->prepend_header( 'X-Disposition-Quarantine', $reason );
25922653
}
25932654

25942655
$top_handler->top_addheader_callback();
25952656

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

0 commit comments

Comments
 (0)