← Index
NYTProf Performance Profile   « line view »
For /usr/local/bin/sa-learn
  Run on Sun Nov 5 02:36:06 2017
Reported on Sun Nov 5 02:56:17 2017

Filename/usr/local/lib/perl5/site_perl/Mail/SpamAssassin/Logger.pm
StatementsExecuted 148213 statements in 912ms
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
4370111625349ms349msMail::SpamAssassin::Logger::::dbgMail::SpamAssassin::Logger::dbg
15190105179ms179msMail::SpamAssassin::Logger::::would_logMail::SpamAssassin::Logger::would_log
1111.17ms24.2msMail::SpamAssassin::Logger::::BEGIN@72Mail::SpamAssassin::Logger::BEGIN@72
51155µs55µsMail::SpamAssassin::Logger::::infoMail::SpamAssassin::Logger::info
11152µs63µsMail::SpamAssassin::Logger::::BEGIN@38Mail::SpamAssassin::Logger::BEGIN@38
11147µs55µsMail::SpamAssassin::Logger::::close_logMail::SpamAssassin::Logger::close_log
11137µs247µsMail::SpamAssassin::Logger::::BEGIN@51Mail::SpamAssassin::Logger::BEGIN@51
11132µs164µsMail::SpamAssassin::Logger::::BEGIN@52Mail::SpamAssassin::Logger::BEGIN@52
11127µs27µsMail::SpamAssassin::Logger::::BEGIN@43Mail::SpamAssassin::Logger::BEGIN@43
11124µs24µsMail::SpamAssassin::Logger::::add_facilitiesMail::SpamAssassin::Logger::add_facilities
11122µs63µsMail::SpamAssassin::Logger::::BEGIN@39Mail::SpamAssassin::Logger::BEGIN@39
11122µs182µsMail::SpamAssassin::Logger::::BEGIN@45Mail::SpamAssassin::Logger::BEGIN@45
11120µs27µsMail::SpamAssassin::Logger::::BEGIN@40Mail::SpamAssassin::Logger::BEGIN@40
11119µs74µsMail::SpamAssassin::Logger::::ENDMail::SpamAssassin::Logger::END
11119µs74µsMail::SpamAssassin::Logger::::BEGIN@41Mail::SpamAssassin::Logger::BEGIN@41
11118µs143µsMail::SpamAssassin::Logger::::BEGIN@53Mail::SpamAssassin::Logger::BEGIN@53
11118µs139µsMail::SpamAssassin::Logger::::BEGIN@54Mail::SpamAssassin::Logger::BEGIN@54
11111µs11µsMail::SpamAssassin::Logger::::BEGIN@44Mail::SpamAssassin::Logger::BEGIN@44
0000s0sMail::SpamAssassin::Logger::::_logMail::SpamAssassin::Logger::_log
0000s0sMail::SpamAssassin::Logger::::addMail::SpamAssassin::Logger::add
0000s0sMail::SpamAssassin::Logger::::log_messageMail::SpamAssassin::Logger::log_message
0000s0sMail::SpamAssassin::Logger::::removeMail::SpamAssassin::Logger::remove
Call graph for these subroutines as a Graphviz dot language file.
Line State
ments		 Time
on line		 Calls Time
in subs		 Code
1# <@LICENSE>
2# Licensed to the Apache Software Foundation (ASF) under one or more
3# contributor license agreements. See the NOTICE file distributed with
4# this work for additional information regarding copyright ownership.
5# The ASF licenses this file to you under the Apache License, Version 2.0
6# (the "License"); you may not use this file except in compliance with
7# the License. You may obtain a copy of the License at:
8#
9# http://www.apache.org/licenses/LICENSE-2.0
10#
11# Unless required by applicable law or agreed to in writing, software
12# distributed under the License is distributed on an "AS IS" BASIS,
13# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14# See the License for the specific language governing permissions and
15# limitations under the License.
16# </@LICENSE>
17
18=head1 NAME
19
20Mail::SpamAssassin::Logger - SpamAssassin logging module
21
22=head1 SYNOPSIS
23
24 use Mail::SpamAssassin::Logger;
25
26 $SIG{__WARN__} = sub {
27 log_message("warn", $_[0]);
28 };
29
30 $SIG{__DIE__} = sub {
31 log_message("error", $_[0]) if !$^S;
32 };
33
34=cut
35
36package Mail::SpamAssassin::Logger;
37
38262µs273µs
# spent 63µs (52+11) within Mail::SpamAssassin::Logger::BEGIN@38 which was called: # once (52µs+11µs) by Mail::SpamAssassin::BEGIN@69 at line 38
use strict;
# spent 63µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@38 # spent 10µs making 1 call to strict::import
39254µs2104µs
# spent 63µs (22+41) within Mail::SpamAssassin::Logger::BEGIN@39 which was called: # once (22µs+41µs) by Mail::SpamAssassin::BEGIN@69 at line 39
use warnings;
# spent 63µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@39 # spent 41µs making 1 call to warnings::import
40255µs234µs
# spent 27µs (20+7) within Mail::SpamAssassin::Logger::BEGIN@40 which was called: # once (20µs+7µs) by Mail::SpamAssassin::BEGIN@69 at line 40
use bytes;
# spent 27µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@40 # spent 7µs making 1 call to bytes::import
41275µs2128µs
# spent 74µs (19+55) within Mail::SpamAssassin::Logger::BEGIN@41 which was called: # once (19µs+55µs) by Mail::SpamAssassin::BEGIN@69 at line 41
use re 'taint';
# spent 74µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@41 # spent 55µs making 1 call to re::import
42
43
# spent 27µs within Mail::SpamAssassin::Logger::BEGIN@43 which was called: # once (27µs+0s) by Mail::SpamAssassin::BEGIN@69 at line 49
BEGIN {
44258µs111µs
# spent 11µs within Mail::SpamAssassin::Logger::BEGIN@44 which was called: # once (11µs+0s) by Mail::SpamAssassin::BEGIN@69 at line 44
use Exporter ();
# spent 11µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@44
45299µs2342µs
# spent 182µs (22+160) within Mail::SpamAssassin::Logger::BEGIN@45 which was called: # once (22µs+160µs) by Mail::SpamAssassin::BEGIN@69 at line 45
use vars qw(@ISA @EXPORT @EXPORT_OK);
# spent 182µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@45 # spent 160µs making 1 call to vars::import
46115µs @ISA = qw(Exporter);
4712µs @EXPORT = qw(dbg info would_log);
48111µs @EXPORT_OK = qw(log_message);
49146µs127µs}
# spent 27µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@43
50
51262µs2457µs
# spent 247µs (37+210) within Mail::SpamAssassin::Logger::BEGIN@51 which was called: # once (37µs+210µs) by Mail::SpamAssassin::BEGIN@69 at line 51
use constant ERROR => 0;
# spent 247µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@51 # spent 210µs making 1 call to constant::import
52259µs2294µs
# spent 164µs (32+131) within Mail::SpamAssassin::Logger::BEGIN@52 which was called: # once (32µs+131µs) by Mail::SpamAssassin::BEGIN@69 at line 52
use constant WARNING => 1;
# spent 164µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@52 # spent 131µs making 1 call to constant::import
53257µs2267µs
# spent 143µs (18+124) within Mail::SpamAssassin::Logger::BEGIN@53 which was called: # once (18µs+124µs) by Mail::SpamAssassin::BEGIN@69 at line 53
use constant INFO => 2;
# spent 143µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@53 # spent 124µs making 1 call to constant::import
542172µs2260µs
# spent 139µs (18+121) within Mail::SpamAssassin::Logger::BEGIN@54 which was called: # once (18µs+121µs) by Mail::SpamAssassin::BEGIN@69 at line 54
use constant DBG => 3;
# spent 139µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@54 # spent 121µs making 1 call to constant::import
55
5619µsmy %log_level = (
57 0 => 'ERROR',
58 1 => 'WARNING',
59 2 => 'INFO',
60 3 => 'DBG',
61 );
62
63# global shared object
64our %LOG_SA;
65our $LOG_ENTERED; # to avoid recursion on die or warn from within logging
66
67# defaults
6813µs$LOG_SA{level} = WARNING; # log info, warnings and errors
6912µs$LOG_SA{facility} = {}; # no dbg facilities turned on
70
71# always log to stderr initially
7223.19ms124.2ms
# spent 24.2ms (1.17+23.0) within Mail::SpamAssassin::Logger::BEGIN@72 which was called: # once (1.17ms+23.0ms) by Mail::SpamAssassin::BEGIN@69 at line 72
use Mail::SpamAssassin::Logger::Stderr;
# spent 24.2ms making 1 call to Mail::SpamAssassin::Logger::BEGIN@72
73115µs140µs$LOG_SA{method}->{stderr} = Mail::SpamAssassin::Logger::Stderr->new();
# spent 40µs making 1 call to Mail::SpamAssassin::Logger::Stderr::new
74
75=head1 METHODS
76
77=over 4
78
79=item add_facilities(facilities)
80
81Enable debug logging for specific facilities. Each facility is the area
82of code to debug. Facilities can be specified as a hash reference (the
83key names are used), an array reference, an array, or a comma-separated
84scalar string. Facility names are case-sensitive.
85
86If "all" is listed, then all debug facilities are implicitly enabled,
87except for those explicitly disabled. A facility name may be preceded
88by a "no" (case-insensitive), which explicitly disables it, overriding
89the "all". For example: all,norules,noconfig,nodcc. When facility names
90are given as an ordered list (array or scalar, not a hash), the last entry
91applies, e.g. 'nodcc,dcc,dcc,noddc' is equivalent to 'nodcc'. Note that
92currently no facility name starts with a "no", it is advised to keep this
93practice with newly added facility names to make life easier.
94
95Higher priority informational messages that are suitable for logging in
96normal circumstances are available with an area of "info". Some very
97verbose messages require the facility to be specifically enabled (see
98C<would_log> below).
99
100=cut
101
102
# spent 24µs within Mail::SpamAssassin::Logger::add_facilities which was called: # once (24µs+0s) by Mail::SpamAssassin::new at line 404 of Mail/SpamAssassin.pm
sub add_facilities {
10313µs my ($facilities) = @_;
104
10512µs my @facilities;
10615µs if (ref ($facilities) eq '') {
10712µs if (defined $facilities && $facilities ne '0') {
108 @facilities = split(/,/, $facilities);
109 }
110 }
111 elsif (ref ($facilities) eq 'ARRAY') {
112 @facilities = @{ $facilities };
113 }
114 elsif (ref ($facilities) eq 'HASH') {
115 @facilities = keys %{ $facilities };
116 }
11714µs @facilities = grep(/^\S+$/, @facilities);
118114µs if (@facilities) {
119 for my $fac (@facilities) {
120 local ($1,$2);
121 $LOG_SA{facility}->{$2} = !defined($1) if $fac =~ /^(no)?(.+)\z/si;
122 }
123 # turn on debugging if facilities other than "info" are enabled
124 if (grep { !/^info\z/ && !/^no./si } keys %{ $LOG_SA{facility} }) {
125 $LOG_SA{level} = DBG if $LOG_SA{level} < DBG;
126 }
127 else {
128 $LOG_SA{level} = INFO if $LOG_SA{level} < INFO;
129 }
130 # debug statement last so we might see it
131 dbg("logger: adding facilities: " . join(", ", @facilities));
132 dbg("logger: logging level is " . $log_level{$LOG_SA{level}});
133 }
134}
135
136=item log_message($level, @message)
137
138Log a message at a specific level. Levels are specified as strings:
139"warn", "error", "info", and "dbg". The first element of the message
140must be prefixed with a facility name followed directly by a colon.
141
142=cut
143
144sub log_message {
145 my ($level, @message) = @_;
146
147 # too many die and warn messages out there, don't log the ones that we don't
148 # own. jm: off: this makes no sense -- if a dependency module dies or warns,
149 # we want to know about it, unless we're *SURE* it's not something worth
150 # worrying about.
151 # if ($level eq "error" or $level eq "warn") {
152 # return unless $message[0] =~ /^\S+:/;
153 # }
154
155 if ($level eq "error") {
156 # don't log alarm timeouts or broken pipes of various plugins' network checks
157 return if ($message[0] =~ /__ignore__/);
158
159 # dos: we can safely ignore any die's that we eval'd in our own modules so
160 # don't log them -- this is caller 0, the use'ing package is 1, the eval is 2
161 my @caller = caller 2;
162 return if (defined $caller[3] && defined $caller[0] &&
163 $caller[3] =~ /^\(eval\)$/ &&
164 $caller[0] =~ m#^Mail::SpamAssassin(?:$|::)#);
165 }
166
167 return if $LOG_ENTERED; # avoid recursion on die or warn from within logging
168 $LOG_ENTERED = 1; # no 'returns' from this point on, must clear the flag
169
170 my $message = join(" ", @message);
171 $message =~ s/[\r\n]+$//; # remove any trailing newlines
172
173 # split on newlines and call log_message multiple times; saves
174 # the subclasses having to understand multi-line logs
175 my $first = 1;
176 foreach my $line (split(/\n/, $message)) {
177 # replace control characters with "_", tabs and spaces get
178 # replaced with a single space.
179 $line =~ tr/\x09\x20\x00-\x1f/ _/s;
180 if ($first) {
181 $first = 0;
182 } else {
183 local $1;
184 $line =~ s/^([^:]+?):/$1: [...]/;
185 }
186 while (my ($name, $object) = each %{ $LOG_SA{method} }) {
187 $object->log_message($level, $line);
188 }
189 }
190 $LOG_ENTERED = 0;
191}
192
193=item dbg("facility: message")
194
195This is used for all low priority debugging messages.
196
197=cut
198
199
# spent 349ms within Mail::SpamAssassin::Logger::dbg which was called 43701 times, avg 8µs/call: # 8426 times (58.2ms+0s) by Mail::SpamAssassin::PerMsgStatus::register_async_rule_start at line 690 of Mail/SpamAssassin/Dns.pm, avg 7µs/call # 6775 times (57.4ms+0s) by Mail::SpamAssassin::AsyncLoop::bgsend_and_start_lookup at line 286 of Mail/SpamAssassin/AsyncLoop.pm, avg 8µs/call # 2209 times (22.6ms+0s) by Mail::SpamAssassin::DBBasedAddrList::get_addr_entry at line 131 of Mail/SpamAssassin/DBBasedAddrList.pm, avg 10µs/call # 2121 times (16.7ms+0s) by Mail::SpamAssassin::DBBasedAddrList::add_score at line 146 of Mail/SpamAssassin/DBBasedAddrList.pm, avg 8µs/call # 1968 times (16.9ms+0s) by Mail::SpamAssassin::DnsResolver::bgsend at line 721 of Mail/SpamAssassin/DnsResolver.pm, avg 9µs/call # 1968 times (14.8ms+0s) by Mail::SpamAssassin::DnsResolver::bgsend at line 695 of Mail/SpamAssassin/DnsResolver.pm, avg 8µs/call # 1968 times (13.8ms+0s) by Mail::SpamAssassin::AsyncLoop::bgsend_and_start_lookup at line 322 of Mail/SpamAssassin/AsyncLoop.pm, avg 7µs/call # 1968 times (13.1ms+0s) by Mail::SpamAssassin::AsyncLoop::start_lookup at line 243 of Mail/SpamAssassin/AsyncLoop.pm, avg 7µs/call # 1968 times (11.8ms+0s) by Mail::SpamAssassin::DnsResolver::bgsend at line 700 of Mail/SpamAssassin/DnsResolver.pm, avg 6µs/call # 1886 times (18.8ms+0s) by Mail::SpamAssassin::Plugin::TxRep::check_reputation at line 1406 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 10µs/call # 1041 times (13.5ms+0s) by Mail::SpamAssassin::Message::Metadata::make_relay_as_string at line 1367 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 13µs/call # 1041 times (8.92ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 230 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 9µs/call # 469 times (4.18ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 177 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 9µs/call # 468 times (3.14ms+0s) by Mail::SpamAssassin::PerMsgStatus::new at line 284 of Mail/SpamAssassin/PerMsgStatus.pm, avg 7µs/call # 466 times (4.37ms+0s) by Mail::SpamAssassin::BayesStore::DBM::tie_db_readonly at line 176 of Mail/SpamAssassin/BayesStore/DBM.pm, avg 9µs/call # 425 times (2.68ms+0s) by Mail::SpamAssassin::Message::_parse_normal at line 1031 of Mail/SpamAssassin/Message.pm, avg 6µs/call # 409 times (2.61ms+0s) by Mail::SpamAssassin::Message::_parse_normal at line 1078 of Mail/SpamAssassin/Message.pm, avg 6µs/call # 388 times (4.00ms+0s) by Mail::SpamAssassin::Message::_parse_multipart at line 924 of Mail/SpamAssassin/Message.pm, avg 10µs/call # 388 times (3.35ms+0s) by Mail::SpamAssassin::Message::Node::add_body_part at line 251 of Mail/SpamAssassin/Message/Node.pm, avg 9µs/call # 383 times (2.92ms+0s) by Mail::SpamAssassin::Plugin::URIDNSBL::query_hosts_or_domains at line 834 of Mail/SpamAssassin/Plugin/URIDNSBL.pm, avg 8µs/call # 321 times (2.87ms+0s) by Mail::SpamAssassin::Plugin::TxRep::check_senders_reputation at line 1310 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 9µs/call # 321 times (2.47ms+0s) by Mail::SpamAssassin::Plugin::TxRep::check_reputation at line 1426 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 8µs/call # 234 times (2.42ms+0s) by Mail::SpamAssassin::Plugin::Bayes::_learn_trapped at line 494 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 10µs/call # 234 times (2.31ms+0s) by Mail::SpamAssassin::Plugin::Bayes::tokenize at line 1067 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 10µs/call # 234 times (2.30ms+0s) by Mail::SpamAssassin::Message::new at line 364 of Mail/SpamAssassin/Message.pm, avg 10µs/call # 234 times (2.04ms+0s) by Mail::SpamAssassin::Plugin::Bayes::tokenize at line 1115 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 9µs/call # 234 times (1.95ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 296 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 8µs/call # 234 times (1.91ms+0s) by Mail::SpamAssassin::parse at line 545 of Mail/SpamAssassin.pm, avg 8µs/call # 234 times (1.86ms+0s) by Mail::SpamAssassin::PerMsgStatus::all_from_addrs at line 3055 of Mail/SpamAssassin/PerMsgStatus.pm, avg 8µs/call # 234 times (1.77ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 99 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 8µs/call # 234 times (1.70ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 297 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 7µs/call # 234 times (1.64ms+0s) by Mail::SpamAssassin::Plugin::Bayes::tokenize at line 1074 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 7µs/call # 234 times (1.60ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 299 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 7µs/call # 234 times (1.59ms+0s) by Mail::SpamAssassin::PerMsgStatus::action_depends_on_tags at line 1403 of Mail/SpamAssassin/PerMsgStatus.pm, avg 7µs/call # 234 times (1.57ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 298 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 7µs/call # 234 times (1.54ms+0s) by Mail::SpamAssassin::Plugin::TxRep::learn_message at line 1772 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 7µs/call # 234 times (1.53ms+0s) by Mail::SpamAssassin::learn at line 654 of Mail/SpamAssassin.pm, avg 7µs/call # 234 times (1.52ms+0s) by Mail::SpamAssassin::Message::parse_body at line 736 of Mail/SpamAssassin/Message.pm, avg 7µs/call # 234 times (1.41ms+0s) by Mail::SpamAssassin::Plugin::Bayes::tokenize at line 1085 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 6µs/call # 234 times (1.41ms+0s) by Mail::SpamAssassin::Message::parse_body at line 811 of Mail/SpamAssassin/Message.pm, avg 6µs/call # 233 times (1.81ms+0s) by Mail::SpamAssassin::BayesStore::DBM::tie_db_readonly at line 204 of Mail/SpamAssassin/BayesStore/DBM.pm, avg 8µs/call # 233 times (1.45ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 192 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 6µs/call # 202 times (1.37ms+0s) by Mail::SpamAssassin::Message::Node::decode at line 338 of Mail/SpamAssassin/Message/Node.pm, avg 7µs/call # 197 times (1.43ms+0s) by Mail::SpamAssassin::Message::_parse_multipart at line 835 of Mail/SpamAssassin/Message.pm, avg 7µs/call # 189 times (1.39ms+0s) by Mail::SpamAssassin::HTML::parse at line 256 of Mail/SpamAssassin/HTML.pm, avg 7µs/call # 128 times (2.02ms+0s) by Mail::SpamAssassin::Conf::__ANON__[/usr/local/lib/perl5/site_perl/Mail/SpamAssassin/Conf.pm:3557] at line 3556 of Mail/SpamAssassin/Conf.pm, avg 16µs/call # 106 times (833µs+0s) by Mail::SpamAssassin::Message::Node::decode at line 362 of Mail/SpamAssassin/Message/Node.pm, avg 8µs/call # 87 times (1.23ms+0s) by Mail::SpamAssassin::Plugin::TxRep::check_senders_reputation at line 1280 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 14µs/call # 87 times (516µs+0s) by Mail::SpamAssassin::Plugin::TxRep::forget_message at line 1795 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 6µs/call # 69 times (441µs+0s) by Mail::SpamAssassin::Conf::Parser::check_for_missing_descriptions at line 659 of Mail/SpamAssassin/Conf/Parser.pm, avg 6µs/call # 68 times (540µs+0s) by Mail::SpamAssassin::read_cf_file at line 1856 of Mail/SpamAssassin.pm, avg 8µs/call # 63 times (403µs+0s) by Mail::SpamAssassin::_read_cf_pre at line 1819 of Mail/SpamAssassin.pm, avg 6µs/call # 58 times (633µs+0s) by Mail::SpamAssassin::Conf::Parser::fix_path_relative_to_current_file at line 1504 of Mail/SpamAssassin/Conf/Parser.pm, avg 11µs/call # 55 times (419µs+0s) by Mail::SpamAssassin::Message::Node::decode at line 343 of Mail/SpamAssassin/Message/Node.pm, avg 8µs/call # 46 times (352µs+0s) by Mail::SpamAssassin::Message::Node::rendered at line 632 of Mail/SpamAssassin/Message/Node.pm, avg 8µs/call # 46 times (313µs+0s) by Mail::SpamAssassin::Message::Node::decode at line 365 of Mail/SpamAssassin/Message/Node.pm, avg 7µs/call # 42 times (356µs+0s) by Mail::SpamAssassin::Plugin::URIDNSBL::parsed_metadata at line 448 of Mail/SpamAssassin/Plugin/URIDNSBL.pm, avg 8µs/call # 39 times (295µs+0s) by Mail::SpamAssassin::Message::new at line 376 of Mail/SpamAssassin/Message.pm, avg 8µs/call # 27 times (299µs+0s) by Mail::SpamAssassin::PluginHandler::load_plugin at line 112 of Mail/SpamAssassin/PluginHandler.pm, avg 11µs/call # 16 times (161µs+0s) by Mail::SpamAssassin::Util::secure_tmpfile at line 1145 of Mail/SpamAssassin/Util.pm, avg 10µs/call # 16 times (125µs+0s) by Mail::SpamAssassin::Message::_parse_normal at line 1069 of Mail/SpamAssassin/Message.pm, avg 8µs/call # 12 times (93µs+0s) by Mail::SpamAssassin::PluginHandler::have_callback at line 173 of Mail/SpamAssassin/PluginHandler.pm, avg 8µs/call # 11 times (121µs+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 149 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 11µs/call # 10 times (130µs+0s) by Mail::SpamAssassin::Conf::Parser::find_dup_rules at line 1081 of Mail/SpamAssassin/Conf/Parser.pm, avg 13µs/call # 7 times (50µs+0s) by Mail::SpamAssassin::Util::clean_path_in_taint_mode at line 179 of Mail/SpamAssassin/Util.pm, avg 7µs/call # 2 times (17µs+0s) by Mail::SpamAssassin::ArchiveIterator::_set_default_message_selection_opts at line 677 of Mail/SpamAssassin/ArchiveIterator.pm, avg 8µs/call # 2 times (17µs+0s) by Mail::SpamAssassin::BayesStore::DBM::tie_db_readonly at line 169 of Mail/SpamAssassin/BayesStore/DBM.pm, avg 8µs/call # 2 times (16µs+0s) by Mail::SpamAssassin::DnsResolver::load_resolver at line 118 of Mail/SpamAssassin/DnsResolver.pm, avg 8µs/call # 2 times (16µs+0s) by Mail::SpamAssassin::Locker::UnixNFSSafe::safe_lock at line 91 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm, avg 8µs/call # 2 times (16µs+0s) by Mail::SpamAssassin::DnsResolver::load_resolver at line 152 of Mail/SpamAssassin/DnsResolver.pm, avg 8µs/call # 2 times (15µs+0s) by Mail::SpamAssassin::Locker::UnixNFSSafe::safe_lock at line 67 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm, avg 8µs/call # 2 times (15µs+0s) by Mail::SpamAssassin::BayesStore::DBM::tie_db_writable at line 293 of Mail/SpamAssassin/BayesStore/DBM.pm, avg 8µs/call # 2 times (15µs+0s) by Mail::SpamAssassin::Conf::set_score_set at line 4632 of Mail/SpamAssassin/Conf.pm, avg 7µs/call # 2 times (15µs+0s) by Mail::SpamAssassin::Locker::UnixNFSSafe::safe_lock at line 84 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm, avg 7µs/call # 2 times (14µs+0s) by Mail::SpamAssassin::Locker::UnixNFSSafe::safe_lock at line 89 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm, avg 7µs/call # 2 times (13µs+0s) by Mail::SpamAssassin::DnsResolver::load_resolver at line 174 of Mail/SpamAssassin/DnsResolver.pm, avg 7µs/call # 2 times (12µs+0s) by Mail::SpamAssassin::DnsResolver::load_resolver at line 161 of Mail/SpamAssassin/DnsResolver.pm, avg 6µs/call # 2 times (11µs+0s) by Mail::SpamAssassin::DnsResolver::load_resolver at line 176 of Mail/SpamAssassin/DnsResolver.pm, avg 6µs/call # 2 times (11µs+0s) by Mail::SpamAssassin::DnsResolver::load_resolver at line 178 of Mail/SpamAssassin/DnsResolver.pm, avg 5µs/call # once (19µs+0s) by Mail::SpamAssassin::Plugin::TxRep::learner_close at line 1826 of Mail/SpamAssassin/Plugin/TxRep.pm # once (18µs+0s) by Mail::SpamAssassin::DBBasedAddrList::new_checker at line 83 of Mail/SpamAssassin/DBBasedAddrList.pm # once (18µs+0s) by Mail::SpamAssassin::DBBasedAddrList::finish at line 112 of Mail/SpamAssassin/DBBasedAddrList.pm # once (16µs+0s) by Mail::SpamAssassin::Plugin::Razor2::new at line 70 of Mail/SpamAssassin/Plugin/Razor2.pm # once (12µs+0s) by Mail::SpamAssassin::Plugin::Bayes::learner_new at line 1666 of Mail/SpamAssassin/Plugin/Bayes.pm # once (12µs+0s) by Mail::SpamAssassin::DnsResolver::pick_random_available_port at line 324 of Mail/SpamAssassin/DnsResolver.pm # once (11µs+0s) by Mail::SpamAssassin::Plugin::TxRep::new at line 232 of Mail/SpamAssassin/Plugin/TxRep.pm # once (11µs+0s) by Mail::SpamAssassin::new at line 407 of Mail/SpamAssassin.pm # once (11µs+0s) by Mail::SpamAssassin::Plugin::SpamCop::new at line 69 of Mail/SpamAssassin/Plugin/SpamCop.pm # once (10µs+0s) by Mail::SpamAssassin::Util::am_running_in_taint_mode at line 213 of Mail/SpamAssassin/Util.pm # once (9µs+0s) by Mail::SpamAssassin::Conf::__ANON__[/usr/local/lib/perl5/site_perl/Mail/SpamAssassin/Conf.pm:3804] at line 3803 of Mail/SpamAssassin/Conf.pm # once (8µs+0s) by Mail::SpamAssassin::Locker::UnixNFSSafe::safe_unlock at line 199 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm # once (8µs+0s) by Mail::SpamAssassin::PerMsgStatus::all_to_addrs at line 3142 of Mail/SpamAssassin/PerMsgStatus.pm # once (8µs+0s) by Mail::SpamAssassin::Conf::Parser::finish_parsing at line 867 of Mail/SpamAssassin/Conf/Parser.pm # once (8µs+0s) by Mail::SpamAssassin::DnsResolver::connect_sock at line 410 of Mail/SpamAssassin/DnsResolver.pm # once (8µs+0s) by Mail::SpamAssassin::PerMsgStatus::clear_resolver at line 449 of Mail/SpamAssassin/Dns.pm # once (8µs+0s) by Mail::SpamAssassin::BayesStore::DBM::untie_db at line 613 of Mail/SpamAssassin/BayesStore/DBM.pm # once (7µs+0s) by Mail::SpamAssassin::Plugin::ReplaceTags::finish_parsing_end at line 173 of Mail/SpamAssassin/Plugin/ReplaceTags.pm # once (7µs+0s) by Mail::SpamAssassin::Plugin::TxRep::check_senders_reputation at line 1301 of Mail/SpamAssassin/Plugin/TxRep.pm # once (7µs+0s) by Mail::SpamAssassin::Plugin::FreeMail::dbg at line 145 of Mail/SpamAssassin/Plugin/FreeMail.pm # once (7µs+0s) by main::RUNTIME at line 237 of /usr/local/bin/sa-learn # once (7µs+0s) by Mail::SpamAssassin::DnsResolver::connect_sock at line 448 of Mail/SpamAssassin/DnsResolver.pm # once (7µs+0s) by Mail::SpamAssassin::DBBasedAddrList::finish at line 109 of Mail/SpamAssassin/DBBasedAddrList.pm # once (7µs+0s) by Mail::SpamAssassin::BayesStore::DBM::untie_db at line 626 of Mail/SpamAssassin/BayesStore/DBM.pm # once (7µs+0s) by Mail::SpamAssassin::Util::clean_path_in_taint_mode at line 184 of Mail/SpamAssassin/Util.pm # once (7µs+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 184 of Mail/SpamAssassin/Message/Metadata/Received.pm # once (7µs+0s) by Mail::SpamAssassin::Plugin::Bayes::learner_new at line 1655 of Mail/SpamAssassin/Plugin/Bayes.pm # once (6µs+0s) by Mail::SpamAssassin::init_learner at line 708 of Mail/SpamAssassin.pm # once (6µs+0s) by Mail::SpamAssassin::BayesStore::DBM::tie_db_writable at line 322 of Mail/SpamAssassin/BayesStore/DBM.pm # once (6µs+0s) by Mail::SpamAssassin::new at line 416 of Mail/SpamAssassin.pm # once (6µs+0s) by Mail::SpamAssassin::Util::clean_path_in_taint_mode at line 164 of Mail/SpamAssassin/Util.pm # once (6µs+0s) by Mail::SpamAssassin::Locker::UnixNFSSafe::safe_unlock at line 204 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm # once (6µs+0s) by Mail::SpamAssassin::DnsResolver::configured_nameservers at line 215 of Mail/SpamAssassin/DnsResolver.pm # once (6µs+0s) by Mail::SpamAssassin::Plugin::ReplaceTags::finish_parsing_end at line 80 of Mail/SpamAssassin/Plugin/ReplaceTags.pm # once (6µs+0s) by Mail::SpamAssassin::Util::clean_path_in_taint_mode at line 138 of Mail/SpamAssassin/Util.pm # once (6µs+0s) by Mail::SpamAssassin::PerMsgStatus::is_dns_available at line 540 of Mail/SpamAssassin/Dns.pm # once (5µs+0s) by Mail::SpamAssassin::DnsResolver::connect_sock at line 356 of Mail/SpamAssassin/DnsResolver.pm
sub dbg {
2004370187.5ms _log(DBG, @_) if $LOG_SA{level} >= DBG;
20143701558ms 1; # always return the same simple value, regardless of log level
202}
203
204=item info("facility: message")
205
206This is used for informational messages indicating a normal, but
207significant, condition. This should be infrequently called. These
208messages are typically logged when SpamAssassin is run as a daemon.
209
210=cut
211
212
# spent 55µs within Mail::SpamAssassin::Logger::info which was called 5 times, avg 11µs/call: # 5 times (55µs+0s) by Mail::SpamAssassin::ArchiveIterator::_run_file at line 381 of Mail/SpamAssassin/ArchiveIterator.pm, avg 11µs/call
sub info {
213515µs _log(INFO, @_) if $LOG_SA{level} >= INFO;
214538µs 1; # always return the same simple value, regardless of log level
215}
216
217# remember to avoid deep recursion, my friend
218sub _log {
219 my $facility;
220 local ($1);
221
222 # it's faster to access this as the $_[1] alias, and not to perform
223 # string mods until we're sure we actually want to log anything
224 if ($_[1] =~ /^([a-z0-9_-]*):/i) {
225 $facility = $1;
226 } else {
227 $facility = "generic";
228 }
229
230 # log all info, warn, and error messages;
231 # only debug if asked to
232 if ($_[0] == DBG) {
233 return unless
234 exists $LOG_SA{facility}->{$facility} ? $LOG_SA{facility}->{$facility}
235 : $LOG_SA{facility}->{all};
236 }
237
238 my ($level, $message, @args) = @_;
239 $message =~ s/^(?:[a-z0-9_-]*):\s*//i;
240
241 $message = sprintf($message,@args) if @args;
242 $message =~ s/\n+$//s;
243 $message =~ s/^/${facility}: /mg;
244
245 # no reason to go through warn()
246 log_message(($level == INFO ? "info" : "dbg"), $message);
247}
248
249=item add(method => 'syslog', socket => $socket, facility => $facility)
250
251C<socket> is the type the syslog ("unix" or "inet"). C<facility> is the
252syslog facility (typically "mail").
253
254=item add(method => 'file', filename => $file)
255
256C<filename> is the name of the log file.
257
258=item add(method => 'stderr')
259
260No options are needed for stderr logging, just don't close stderr first.
261
262=cut
263
264sub add {
265 my %params = @_;
266
267 my $name = lc($params{method});
268 my $class = ucfirst($name);
269
270 eval 'use Mail::SpamAssassin::Logger::'.$class.'; 1'
271 or do {
272 my $eval_stat = $@ ne '' ? $@ : "errno=$!"; chomp $eval_stat;
273 die "logger: add $class failed: $eval_stat\n";
274 };
275
276 if (!exists $LOG_SA{method}->{$name}) {
277 my $object;
278 my $eval_stat;
279 eval '$object = Mail::SpamAssassin::Logger::'.$class.'->new(%params); 1'
280 or do {
281 $eval_stat = $@ ne '' ? $@ : "errno=$!"; chomp $eval_stat;
282 undef $object; # just in case
283 };
284 if (!$object) {
285 if (!defined $eval_stat) {
286 $eval_stat = "Mail::SpamAssassin::Logger::$class->new ".
287 "failed to return an object";
288 }
289 warn "logger: failed to add $name method: $eval_stat\n";
290 }
291 else {
292 $LOG_SA{method}->{$name} = $object;
293 dbg("logger: successfully added $name method\n");
294 return 1;
295 }
296 return 0;
297 }
298
299 warn "logger: $name method already added\n";
300 return 1;
301}
302
303=item remove(method)
304
305Remove a logging method. Only the method name needs to be passed as a
306scalar.
307
308=cut
309
310sub remove {
311 my ($method) = @_;
312
313 my $name = lc($method);
314 if (exists $LOG_SA{method}->{$name}) {
315 delete $LOG_SA{method}->{$name};
316 info("logger: removing $name method");
317 return 1;
318 }
319 warn "logger: unable to remove $name method, not present to be removed\n";
320 return 1;
321}
322
323=item would_log($level, $facility)
324
325Returns false if a message at the given level and with the given facility
326would not be logged. Returns 1 if a message at a given level and facility
327would be logged normally. Returns 2 if the facility was specifically
328enabled.
329
330The facility argument is optional.
331
332=cut
333
334
# spent 179ms within Mail::SpamAssassin::Logger::would_log which was called 15190 times, avg 12µs/call: # 5374 times (59.7ms+0s) by Mail::SpamAssassin::Plugin::Bayes::_tokenize_headers at line 1371 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 11µs/call # 4211 times (47.7ms+0s) by Mail::SpamAssassin::PerMsgStatus::get_uri_detail_list at line 2287 of Mail/SpamAssassin/PerMsgStatus.pm, avg 11µs/call # 3028 times (39.8ms+0s) by Mail::SpamAssassin::PerMsgStatus::tag_is_ready at line 1426 of Mail/SpamAssassin/PerMsgStatus.pm, avg 13µs/call # 1718 times (19.6ms+0s) by Mail::SpamAssassin::PerMsgStatus::get_uri_detail_list at line 2329 of Mail/SpamAssassin/PerMsgStatus.pm, avg 11µs/call # 468 times (7.58ms+0s) by Mail::SpamAssassin::PerMsgStatus::new at line 297 of Mail/SpamAssassin/PerMsgStatus.pm, avg 16µs/call # 234 times (3.41ms+0s) by Mail::SpamAssassin::Plugin::AskDNS::extract_metadata at line 380 of Mail/SpamAssassin/Plugin/AskDNS.pm, avg 15µs/call # 84 times (880µs+0s) by Mail::SpamAssassin::Plugin::ReplaceTags::finish_parsing_end at line 158 of Mail/SpamAssassin/Plugin/ReplaceTags.pm, avg 10µs/call # 71 times (731µs+0s) by Mail::SpamAssassin::Plugin::ReplaceTags::finish_parsing_end at line 93 of Mail/SpamAssassin/Plugin/ReplaceTags.pm, avg 10µs/call # once (17µs+0s) by Mail::SpamAssassin::init at line 1756 of Mail/SpamAssassin.pm # once (16µs+0s) by Mail::SpamAssassin::new at line 427 of Mail/SpamAssassin.pm
sub would_log {
3351519033.4ms my ($level, $facility) = @_;
336
3371519027.3ms if ($level eq "info") {
338 return $LOG_SA{level} >= INFO;
339 }
3401519028.9ms if ($level eq "dbg") {
34115190173ms return 0 if $LOG_SA{level} < DBG;
342 return 1 if !$facility;
343 return ($LOG_SA{facility}->{$facility} ? 2 : 0)
344 if exists $LOG_SA{facility}->{$facility};
345 return 1 if $LOG_SA{facility}->{all};
346 return 0;
347 }
348 warn "logger: would_log called with unknown level: $level\n";
349 return 0;
350}
351
352=item close_log()
353
354Close all logs.
355
356=cut
357
358
# spent 55µs (47+8) within Mail::SpamAssassin::Logger::close_log which was called: # once (47µs+8µs) by Mail::SpamAssassin::Logger::END at line 365
sub close_log {
359335µs while (my ($name, $object) = each %{ $LOG_SA{method} }) {
360111µs18µs $object->close_log();
# spent 8µs making 1 call to Mail::SpamAssassin::Logger::Stderr::close_log
361 }
362}
363
364
# spent 74µs (19+55) within Mail::SpamAssassin::Logger::END which was called: # once (19µs+55µs) by main::RUNTIME at line 0 of /usr/local/bin/sa-learn
END {
365117µs155µs close_log();
# spent 55µs making 1 call to Mail::SpamAssassin::Logger::close_log
366}
367
368115µs1;
369
370=back
371
372=cut
Report produced by the NYTProf 6.04 Perl profiler, developed by Tim Bunce based on work by Adam Kaplan and Salvador Fandiño García.