← Index
NYTProf Performance Profile   « line view »
For /usr/local/bin/sa-learn
  Run on Tue Nov 7 05:38:10 2017
Reported on Tue Nov 7 06:16:00 2017

Filename/usr/local/lib/perl5/site_perl/Mail/SpamAssassin/Logger.pm
StatementsExecuted 153933 statements in 976ms
Subroutines
Calls P F Exclusive
Time		 Inclusive
Time		 Subroutine
4674911825374ms374msMail::SpamAssassin::Logger::::dbgMail::SpamAssassin::Logger::dbg
15096105189ms189msMail::SpamAssassin::Logger::::would_logMail::SpamAssassin::Logger::would_log
1111.17ms24.2msMail::SpamAssassin::Logger::::BEGIN@72Mail::SpamAssassin::Logger::BEGIN@72
51156µs56µsMail::SpamAssassin::Logger::::infoMail::SpamAssassin::Logger::info
11154µs62µsMail::SpamAssassin::Logger::::close_logMail::SpamAssassin::Logger::close_log
11146µs54µsMail::SpamAssassin::Logger::::BEGIN@38Mail::SpamAssassin::Logger::BEGIN@38
11137µs240µsMail::SpamAssassin::Logger::::BEGIN@51Mail::SpamAssassin::Logger::BEGIN@51
11135µs238µsMail::SpamAssassin::Logger::::BEGIN@45Mail::SpamAssassin::Logger::BEGIN@45
11130µs229µsMail::SpamAssassin::Logger::::BEGIN@52Mail::SpamAssassin::Logger::BEGIN@52
11128µs33µsMail::SpamAssassin::Logger::::BEGIN@40Mail::SpamAssassin::Logger::BEGIN@40
11128µs102µsMail::SpamAssassin::Logger::::BEGIN@41Mail::SpamAssassin::Logger::BEGIN@41
11124µs24µsMail::SpamAssassin::Logger::::add_facilitiesMail::SpamAssassin::Logger::add_facilities
11122µs22µsMail::SpamAssassin::Logger::::BEGIN@43Mail::SpamAssassin::Logger::BEGIN@43
11121µs62µsMail::SpamAssassin::Logger::::BEGIN@39Mail::SpamAssassin::Logger::BEGIN@39
11120µs223µsMail::SpamAssassin::Logger::::BEGIN@54Mail::SpamAssassin::Logger::BEGIN@54
11120µs82µsMail::SpamAssassin::Logger::::ENDMail::SpamAssassin::Logger::END
11118µs198µsMail::SpamAssassin::Logger::::BEGIN@53Mail::SpamAssassin::Logger::BEGIN@53
11112µs12µ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
38263µs262µs
# spent 54µs (46+8) within Mail::SpamAssassin::Logger::BEGIN@38 which was called: # once (46µs+8µs) by Mail::SpamAssassin::BEGIN@69 at line 38
use strict;
# spent 54µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@38 # spent 8µs making 1 call to strict::import
39262µs2102µs
# spent 62µs (21+40) within Mail::SpamAssassin::Logger::BEGIN@39 which was called: # once (21µs+40µs) by Mail::SpamAssassin::BEGIN@69 at line 39
use warnings;
# spent 62µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@39 # spent 40µs making 1 call to warnings::import
40273µs238µs
# spent 33µs (28+5) within Mail::SpamAssassin::Logger::BEGIN@40 which was called: # once (28µs+5µs) by Mail::SpamAssassin::BEGIN@69 at line 40
use bytes;
# spent 33µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@40 # spent 5µs making 1 call to bytes::import
41286µs2177µs
# spent 102µs (28+75) within Mail::SpamAssassin::Logger::BEGIN@41 which was called: # once (28µs+75µs) by Mail::SpamAssassin::BEGIN@69 at line 41
use re 'taint';
# spent 102µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@41 # spent 75µs making 1 call to re::import
42
43
# spent 22µs within Mail::SpamAssassin::Logger::BEGIN@43 which was called: # once (22µs+0s) by Mail::SpamAssassin::BEGIN@69 at line 49
BEGIN {
44263µs112µs
# spent 12µs within Mail::SpamAssassin::Logger::BEGIN@44 which was called: # once (12µs+0s) by Mail::SpamAssassin::BEGIN@69 at line 44
use Exporter ();
# spent 12µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@44
452121µs2440µs
# spent 238µs (35+203) within Mail::SpamAssassin::Logger::BEGIN@45 which was called: # once (35µs+203µs) by Mail::SpamAssassin::BEGIN@69 at line 45
use vars qw(@ISA @EXPORT @EXPORT_OK);
# spent 238µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@45 # spent 203µs making 1 call to vars::import
46110µs @ISA = qw(Exporter);
4713µs @EXPORT = qw(dbg info would_log);
48112µs @EXPORT_OK = qw(log_message);
49149µs122µs}
# spent 22µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@43
50
51294µs2442µs
# spent 240µs (37+203) within Mail::SpamAssassin::Logger::BEGIN@51 which was called: # once (37µs+203µs) by Mail::SpamAssassin::BEGIN@69 at line 51
use constant ERROR => 0;
# spent 240µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@51 # spent 203µs making 1 call to constant::import
52265µs2428µs
# spent 229µs (30+199) within Mail::SpamAssassin::Logger::BEGIN@52 which was called: # once (30µs+199µs) by Mail::SpamAssassin::BEGIN@69 at line 52
use constant WARNING => 1;
# spent 229µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@52 # spent 199µs making 1 call to constant::import
53268µs2378µs
# spent 198µs (18+180) within Mail::SpamAssassin::Logger::BEGIN@53 which was called: # once (18µs+180µs) by Mail::SpamAssassin::BEGIN@69 at line 53
use constant INFO => 2;
# spent 198µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@53 # spent 180µs making 1 call to constant::import
542192µs2426µs
# spent 223µs (20+203) within Mail::SpamAssassin::Logger::BEGIN@54 which was called: # once (20µs+203µs) by Mail::SpamAssassin::BEGIN@69 at line 54
use constant DBG => 3;
# spent 223µs making 1 call to Mail::SpamAssassin::Logger::BEGIN@54 # spent 203µs making 1 call to constant::import
55
56110µ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
6913µs$LOG_SA{facility} = {}; # no dbg facilities turned on
70
71# always log to stderr initially
7223.18ms124.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
73111µ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 {
10312µ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);
118111µ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 374ms within Mail::SpamAssassin::Logger::dbg which was called 46749 times, avg 8µs/call: # 8426 times (58.9ms+0s) by Mail::SpamAssassin::PerMsgStatus::register_async_rule_start at line 690 of Mail/SpamAssassin/Dns.pm, avg 7µs/call # 6775 times (58.6ms+0s) by Mail::SpamAssassin::AsyncLoop::bgsend_and_start_lookup at line 286 of Mail/SpamAssassin/AsyncLoop.pm, avg 9µs/call # 3118 times (30.9ms+0s) by Mail::SpamAssassin::DBBasedAddrList::get_addr_entry at line 131 of Mail/SpamAssassin/DBBasedAddrList.pm, avg 10µs/call # 2898 times (24.5ms+0s) by Mail::SpamAssassin::DBBasedAddrList::add_score at line 146 of Mail/SpamAssassin/DBBasedAddrList.pm, avg 8µs/call # 2661 times (23.1ms+0s) by Mail::SpamAssassin::Plugin::TxRep::check_reputation at line 1462 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 9µs/call # 1968 times (16.8ms+0s) by Mail::SpamAssassin::DnsResolver::bgsend at line 721 of Mail/SpamAssassin/DnsResolver.pm, avg 9µs/call # 1968 times (14.6ms+0s) by Mail::SpamAssassin::DnsResolver::bgsend at line 695 of Mail/SpamAssassin/DnsResolver.pm, avg 7µ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.2ms+0s) by Mail::SpamAssassin::AsyncLoop::start_lookup at line 243 of Mail/SpamAssassin/AsyncLoop.pm, avg 7µs/call # 1968 times (12.5ms+0s) by Mail::SpamAssassin::DnsResolver::bgsend at line 700 of Mail/SpamAssassin/DnsResolver.pm, avg 6µs/call # 1045 times (13.2ms+0s) by Mail::SpamAssassin::Message::Metadata::make_relay_as_string at line 1367 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 13µs/call # 1045 times (8.78ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 230 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 8µs/call # 471 times (3.88ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 177 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 8µs/call # 470 times (3.17ms+0s) by Mail::SpamAssassin::PerMsgStatus::new at line 284 of Mail/SpamAssassin/PerMsgStatus.pm, avg 7µs/call # 468 times (4.28ms+0s) by Mail::SpamAssassin::BayesStore::DBM::tie_db_readonly at line 176 of Mail/SpamAssassin/BayesStore/DBM.pm, avg 9µs/call # 453 times (4.65ms+0s) by Mail::SpamAssassin::Plugin::TxRep::check_senders_reputation at line 1328 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 10µs/call # 453 times (3.75ms+0s) by Mail::SpamAssassin::Plugin::TxRep::check_reputation at line 1487 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 8µs/call # 427 times (2.60ms+0s) by Mail::SpamAssassin::Message::_parse_normal at line 1031 of Mail/SpamAssassin/Message.pm, avg 6µs/call # 411 times (2.55ms+0s) by Mail::SpamAssassin::Message::_parse_normal at line 1078 of Mail/SpamAssassin/Message.pm, avg 6µs/call # 390 times (3.29ms+0s) by Mail::SpamAssassin::Message::Node::add_body_part at line 251 of Mail/SpamAssassin/Message/Node.pm, avg 8µs/call # 390 times (3.15ms+0s) by Mail::SpamAssassin::Message::_parse_multipart at line 924 of Mail/SpamAssassin/Message.pm, avg 8µs/call # 383 times (2.94ms+0s) by Mail::SpamAssassin::Plugin::URIDNSBL::query_hosts_or_domains at line 834 of Mail/SpamAssassin/Plugin/URIDNSBL.pm, avg 8µs/call # 235 times (2.37ms+0s) by Mail::SpamAssassin::Plugin::Bayes::_learn_trapped at line 494 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 10µs/call # 235 times (2.29ms+0s) by Mail::SpamAssassin::Plugin::Bayes::tokenize at line 1067 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 10µs/call # 235 times (2.23ms+0s) by Mail::SpamAssassin::Message::new at line 364 of Mail/SpamAssassin/Message.pm, avg 10µs/call # 235 times (1.95ms+0s) by Mail::SpamAssassin::Plugin::Bayes::tokenize at line 1115 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 8µs/call # 235 times (1.93ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 296 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 8µs/call # 235 times (1.83ms+0s) by Mail::SpamAssassin::PerMsgStatus::all_from_addrs at line 3055 of Mail/SpamAssassin/PerMsgStatus.pm, avg 8µs/call # 235 times (1.81ms+0s) by Mail::SpamAssassin::parse at line 545 of Mail/SpamAssassin.pm, avg 8µs/call # 235 times (1.72ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 99 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 7µs/call # 235 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 # 235 times (1.62ms+0s) by Mail::SpamAssassin::Plugin::Bayes::tokenize at line 1074 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 7µs/call # 235 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 # 235 times (1.56ms+0s) by Mail::SpamAssassin::PerMsgStatus::action_depends_on_tags at line 1403 of Mail/SpamAssassin/PerMsgStatus.pm, avg 7µs/call # 235 times (1.55ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 298 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 7µs/call # 235 times (1.52ms+0s) by Mail::SpamAssassin::learn at line 654 of Mail/SpamAssassin.pm, avg 6µs/call # 235 times (1.51ms+0s) by Mail::SpamAssassin::Plugin::TxRep::learn_message at line 1836 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 6µs/call # 235 times (1.47ms+0s) by Mail::SpamAssassin::Message::parse_body at line 736 of Mail/SpamAssassin/Message.pm, avg 6µs/call # 235 times (1.39ms+0s) by Mail::SpamAssassin::Message::parse_body at line 811 of Mail/SpamAssassin/Message.pm, avg 6µs/call # 235 times (1.39ms+0s) by Mail::SpamAssassin::Plugin::Bayes::tokenize at line 1085 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 6µs/call # 234 times (1.88ms+0s) by Mail::SpamAssassin::BayesStore::DBM::tie_db_readonly at line 204 of Mail/SpamAssassin/BayesStore/DBM.pm, avg 8µs/call # 234 times (1.46ms+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 192 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 6µs/call # 218 times (3.04ms+0s) by Mail::SpamAssassin::Plugin::TxRep::check_senders_reputation at line 1295 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 14µs/call # 218 times (1.29ms+0s) by Mail::SpamAssassin::Plugin::TxRep::forget_message at line 1859 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 6µs/call # 203 times (1.34ms+0s) by Mail::SpamAssassin::Message::Node::decode at line 338 of Mail/SpamAssassin/Message/Node.pm, avg 7µs/call # 198 times (1.38ms+0s) by Mail::SpamAssassin::Message::_parse_multipart at line 835 of Mail/SpamAssassin/Message.pm, avg 7µs/call # 190 times (1.31ms+0s) by Mail::SpamAssassin::HTML::parse at line 256 of Mail/SpamAssassin/HTML.pm, avg 7µs/call # 128 times (1.84ms+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 14µs/call # 107 times (804µs+0s) by Mail::SpamAssassin::Message::Node::decode at line 362 of Mail/SpamAssassin/Message/Node.pm, avg 8µs/call # 69 times (474µs+0s) by Mail::SpamAssassin::Conf::Parser::check_for_missing_descriptions at line 659 of Mail/SpamAssassin/Conf/Parser.pm, avg 7µs/call # 68 times (571µs+0s) by Mail::SpamAssassin::read_cf_file at line 1856 of Mail/SpamAssassin.pm, avg 8µs/call # 63 times (393µs+0s) by Mail::SpamAssassin::_read_cf_pre at line 1819 of Mail/SpamAssassin.pm, avg 6µs/call # 58 times (698µs+0s) by Mail::SpamAssassin::Conf::Parser::fix_path_relative_to_current_file at line 1504 of Mail/SpamAssassin/Conf/Parser.pm, avg 12µs/call # 55 times (402µs+0s) by Mail::SpamAssassin::Message::Node::decode at line 343 of Mail/SpamAssassin/Message/Node.pm, avg 7µs/call # 46 times (338µs+0s) by Mail::SpamAssassin::Message::Node::rendered at line 632 of Mail/SpamAssassin/Message/Node.pm, avg 7µs/call # 46 times (302µs+0s) by Mail::SpamAssassin::Message::Node::decode at line 365 of Mail/SpamAssassin/Message/Node.pm, avg 7µs/call # 42 times (403µs+0s) by Mail::SpamAssassin::Plugin::URIDNSBL::parsed_metadata at line 448 of Mail/SpamAssassin/Plugin/URIDNSBL.pm, avg 10µs/call # 40 times (282µs+0s) by Mail::SpamAssassin::Message::new at line 376 of Mail/SpamAssassin/Message.pm, avg 7µs/call # 27 times (266µs+0s) by Mail::SpamAssassin::PluginHandler::load_plugin at line 112 of Mail/SpamAssassin/PluginHandler.pm, avg 10µs/call # 16 times (124µs+0s) by Mail::SpamAssassin::Util::secure_tmpfile at line 1145 of Mail/SpamAssassin/Util.pm, avg 8µs/call # 16 times (93µs+0s) by Mail::SpamAssassin::Message::_parse_normal at line 1069 of Mail/SpamAssassin/Message.pm, avg 6µs/call # 12 times (105µs+0s) by Mail::SpamAssassin::PluginHandler::have_callback at line 173 of Mail/SpamAssassin/PluginHandler.pm, avg 9µs/call # 11 times (110µs+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 149 of Mail/SpamAssassin/Message/Metadata/Received.pm, avg 10µs/call # 10 times (114µs+0s) by Mail::SpamAssassin::Conf::Parser::find_dup_rules at line 1081 of Mail/SpamAssassin/Conf/Parser.pm, avg 11µs/call # 7 times (45µs+0s) by Mail::SpamAssassin::Util::clean_path_in_taint_mode at line 179 of Mail/SpamAssassin/Util.pm, avg 6µs/call # 6 times (99µs+0s) by Mail::SpamAssassin::Locker::UnixNFSSafe::safe_lock at line 89 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm, avg 16µs/call # 4 times (38µs+0s) by Mail::SpamAssassin::BayesStore::DBM::tie_db_writable at line 293 of Mail/SpamAssassin/BayesStore/DBM.pm, avg 9µs/call # 3 times (36µs+0s) by Mail::SpamAssassin::Locker::UnixNFSSafe::safe_lock at line 67 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm, avg 12µs/call # 3 times (26µs+0s) by Mail::SpamAssassin::Locker::UnixNFSSafe::safe_lock at line 84 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm, avg 9µs/call # 3 times (19µs+0s) by Mail::SpamAssassin::Locker::UnixNFSSafe::safe_lock at line 91 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm, avg 6µs/call # 2 times (24µs+0s) by Mail::SpamAssassin::BayesStore::DBM::untie_db at line 626 of Mail/SpamAssassin/BayesStore/DBM.pm, avg 12µs/call # 2 times (23µs+0s) by Mail::SpamAssassin::Plugin::TxRep::check_senders_reputation at line 1316 of Mail/SpamAssassin/Plugin/TxRep.pm, avg 11µs/call # 2 times (19µs+0s) by Mail::SpamAssassin::Conf::set_score_set at line 4632 of Mail/SpamAssassin/Conf.pm, avg 9µ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 9µ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 (15µs+0s) by Mail::SpamAssassin::BayesStore::DBM::tie_db_readonly at line 169 of Mail/SpamAssassin/BayesStore/DBM.pm, avg 7µs/call # 2 times (14µs+0s) by Mail::SpamAssassin::DnsResolver::load_resolver at line 161 of Mail/SpamAssassin/DnsResolver.pm, avg 7µs/call # 2 times (14µs+0s) by Mail::SpamAssassin::DnsResolver::load_resolver at line 152 of Mail/SpamAssassin/DnsResolver.pm, avg 7µs/call # 2 times (13µs+0s) by Mail::SpamAssassin::BayesStore::DBM::untie_db at line 613 of Mail/SpamAssassin/BayesStore/DBM.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 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 (18µs+0s) by Mail::SpamAssassin::Plugin::TxRep::learner_close at line 1890 of Mail/SpamAssassin/Plugin/TxRep.pm # once (16µs+0s) by main::RUNTIME at line 237 of /usr/local/bin/sa-learn # once (15µs+0s) by Mail::SpamAssassin::init_learner at line 708 of Mail/SpamAssassin.pm # once (15µ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 (14µs+0s) by Mail::SpamAssassin::Plugin::Razor2::new at line 70 of Mail/SpamAssassin/Plugin/Razor2.pm # once (14µs+0s) by Mail::SpamAssassin::DBBasedAddrList::finish at line 112 of Mail/SpamAssassin/DBBasedAddrList.pm # once (11µs+0s) by Mail::SpamAssassin::Plugin::Bayes::learner_new at line 1666 of Mail/SpamAssassin/Plugin/Bayes.pm # once (11µs+0s) by Mail::SpamAssassin::Plugin::TxRep::new at line 236 of Mail/SpamAssassin/Plugin/TxRep.pm # once (11µs+0s) by Mail::SpamAssassin::DnsResolver::connect_sock at line 448 of Mail/SpamAssassin/DnsResolver.pm # once (10µs+0s) by Mail::SpamAssassin::new at line 407 of Mail/SpamAssassin.pm # once (10µs+0s) by Mail::SpamAssassin::Plugin::SpamCop::new at line 69 of Mail/SpamAssassin/Plugin/SpamCop.pm # once (10µs+0s) by Mail::SpamAssassin::DnsResolver::pick_random_available_port at line 324 of Mail/SpamAssassin/DnsResolver.pm # once (9µs+0s) by Mail::SpamAssassin::Util::am_running_in_taint_mode at line 213 of Mail/SpamAssassin/Util.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::Locker::UnixNFSSafe::safe_unlock at line 199 of Mail/SpamAssassin/Locker/UnixNFSSafe.pm # once (8µs+0s) by Mail::SpamAssassin::BayesStore::DBM::tie_db_writable at line 309 of Mail/SpamAssassin/BayesStore/DBM.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::BayesStore::DBM::tie_db_writable at line 322 of Mail/SpamAssassin/BayesStore/DBM.pm # once (8µs+0s) by Mail::SpamAssassin::Plugin::ReplaceTags::finish_parsing_end at line 173 of Mail/SpamAssassin/Plugin/ReplaceTags.pm # once (8µs+0s) by Mail::SpamAssassin::Conf::Parser::finish_parsing at line 867 of Mail/SpamAssassin/Conf/Parser.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::DBBasedAddrList::new_checker at line 83 of Mail/SpamAssassin/DBBasedAddrList.pm # once (7µs+0s) by Mail::SpamAssassin::DnsResolver::configured_nameservers at line 215 of Mail/SpamAssassin/DnsResolver.pm # once (7µs+0s) by Mail::SpamAssassin::Plugin::Bayes::learner_new at line 1655 of Mail/SpamAssassin/Plugin/Bayes.pm # once (7µs+0s) by Mail::SpamAssassin::Plugin::FreeMail::dbg at line 145 of Mail/SpamAssassin/Plugin/FreeMail.pm # once (6µs+0s) by Mail::SpamAssassin::Message::Metadata::parse_received_headers at line 184 of Mail/SpamAssassin/Message/Metadata/Received.pm # once (6µs+0s) by Mail::SpamAssassin::new at line 416 of Mail/SpamAssassin.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::Locker::UnixNFSSafe::safe_lock at line 111 of Mail/SpamAssassin/Locker/UnixNFSSafe.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::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 184 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 (6µs+0s) by Mail::SpamAssassin::PerMsgStatus::clear_resolver at line 449 of Mail/SpamAssassin/Dns.pm # once (5µs+0s) by Mail::SpamAssassin::DnsResolver::connect_sock at line 356 of Mail/SpamAssassin/DnsResolver.pm # once (5µs+0s) by Mail::SpamAssassin::Util::clean_path_in_taint_mode at line 138 of Mail/SpamAssassin/Util.pm
sub dbg {
2004674993.6ms _log(DBG, @_) if $LOG_SA{level} >= DBG;
20146749605ms 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 56µs within Mail::SpamAssassin::Logger::info which was called 5 times, avg 11µs/call: # 5 times (56µs+0s) by Mail::SpamAssassin::ArchiveIterator::_run_file at line 381 of Mail/SpamAssassin/ArchiveIterator.pm, avg 11µs/call
sub info {
213513µs _log(INFO, @_) if $LOG_SA{level} >= INFO;
214543µ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 189ms within Mail::SpamAssassin::Logger::would_log which was called 15096 times, avg 13µs/call: # 5396 times (59.1ms+0s) by Mail::SpamAssassin::Plugin::Bayes::_tokenize_headers at line 1371 of Mail/SpamAssassin/Plugin/Bayes.pm, avg 11µs/call # 4211 times (54.4ms+0s) by Mail::SpamAssassin::PerMsgStatus::get_uri_detail_list at line 2287 of Mail/SpamAssassin/PerMsgStatus.pm, avg 13µs/call # 2909 times (41.4ms+0s) by Mail::SpamAssassin::PerMsgStatus::tag_is_ready at line 1426 of Mail/SpamAssassin/PerMsgStatus.pm, avg 14µs/call # 1718 times (21.9ms+0s) by Mail::SpamAssassin::PerMsgStatus::get_uri_detail_list at line 2329 of Mail/SpamAssassin/PerMsgStatus.pm, avg 13µs/call # 470 times (7.67ms+0s) by Mail::SpamAssassin::PerMsgStatus::new at line 297 of Mail/SpamAssassin/PerMsgStatus.pm, avg 16µs/call # 235 times (3.21ms+0s) by Mail::SpamAssassin::Plugin::AskDNS::extract_metadata at line 380 of Mail/SpamAssassin/Plugin/AskDNS.pm, avg 14µs/call # 84 times (930µs+0s) by Mail::SpamAssassin::Plugin::ReplaceTags::finish_parsing_end at line 158 of Mail/SpamAssassin/Plugin/ReplaceTags.pm, avg 11µs/call # 71 times (738µs+0s) by Mail::SpamAssassin::Plugin::ReplaceTags::finish_parsing_end at line 93 of Mail/SpamAssassin/Plugin/ReplaceTags.pm, avg 10µs/call # once (16µs+0s) by Mail::SpamAssassin::new at line 427 of Mail/SpamAssassin.pm # once (15µs+0s) by Mail::SpamAssassin::init at line 1756 of Mail/SpamAssassin.pm
sub would_log {
3351509632.6ms my ($level, $facility) = @_;
336
3371509626.7ms if ($level eq "info") {
338 return $LOG_SA{level} >= INFO;
339 }
3401509627.8ms if ($level eq "dbg") {
34115096186ms 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 62µs (54+8) within Mail::SpamAssassin::Logger::close_log which was called: # once (54µs+8µs) by Mail::SpamAssassin::Logger::END at line 365
sub close_log {
359343µ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 82µs (20+62) within Mail::SpamAssassin::Logger::END which was called: # once (20µs+62µs) by main::RUNTIME at line 0 of /usr/local/bin/sa-learn
END {
365118µs162µs close_log();
# spent 62µs making 1 call to Mail::SpamAssassin::Logger::close_log
366}
367
368116µ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.