| File: | blib/lib/Log/Abstraction.pm |
| Coverage: | 94.8% |
| line | stmt | bran | cond | sub | time | code |
|---|---|---|---|---|---|---|
| 1 | package Log::Abstraction; | |||||
| 2 | ||||||
| 3 | # TODO: OpenTelemetry (OTel) Logs backend â not yet implemented. | |||||
| 4 | # | |||||
| 5 | # The goal is to route log messages to an OTel collector via | |||||
| 6 | # OpenTelemetry::Logs::Logger->emit_record(), allowing Log::Abstraction | |||||
| 7 | # to participate in a unified traces+logs+metrics pipeline. | |||||
| 8 | # | |||||
| 9 | # Why it is blocked (last assessed 2026-07-10, OTel Perl v0.033): | |||||
| 10 | # | |||||
| 11 | # 1. emit_record() is a no-op stub. OpenTelemetry::Logs::Logger | |||||
| 12 | # contains "method emit_record ( %args ) { }" â every call is | |||||
| 13 | # silently discarded. This has been the case since logs were added | |||||
| 14 | # as "experimental" in v0.023 (June 2024). | |||||
| 15 | # | |||||
| 16 | # 2. The SDK has no Logs implementation at all. SDK::Trace::* is | |||||
| 17 | # complete (providers, processors, samplers, OTLP exporter), but | |||||
| 18 | # there is no SDK::Logs::LogRecord, no Batch/Simple processor, and | |||||
| 19 | # no SDK::Logs::LoggerProvider. OpenTelemetry::Exporter::OTLP::Logs | |||||
| 20 | # exists as a module but has no processor pipeline to feed it. | |||||
| 21 | # | |||||
| 22 | # 3. The official Log::Any::Adapter::OpenTelemetry has a documented | |||||
| 23 | # FIXME: it cannot safely cache the Logger at construction time, | |||||
| 24 | # because acquiring a Logger before a real LoggerProvider is | |||||
| 25 | # registered returns a no-op that can never be upgraded. This is | |||||
| 26 | # an unresolved architectural issue upstream. | |||||
| 27 | # | |||||
| 28 | # 4. is_debug() / is_* detection in the OTel adapter reads | |||||
| 29 | # otel_config('LOG_LEVEL'), which is the SDK's own internal | |||||
| 30 | # diagnostic level, not the application log level â a semantic bug | |||||
| 31 | # that would propagate into any adapter we write on top. | |||||
| 32 | # | |||||
| 33 | # 5. The Logs stack depends on Object::Pad (Corinna), adding a | |||||
| 34 | # non-trivial dependency and Perl >= 5.26 requirement in practice. | |||||
| 35 | # | |||||
| 36 | # When to revisit: watch for OpenTelemetry::SDK::Logs::LogRecord::Processor | |||||
| 37 | # appearing on CPAN. That signals the end-to-end SDK pipe is functional. | |||||
| 38 | # Estimated: late 2026, based on the Trace SDK timeline (~6-9 months after | |||||
| 39 | # the Trace API stabilised). | |||||
| 40 | # | |||||
| 41 | # Implementation sketch (for when the above blockers are resolved): | |||||
| 42 | # - Add an 'opentelemetry' sub-key to the HASH logger backend. | |||||
| 43 | # - In _log: call otel_logger_provider()->logger()->emit_record( | |||||
| 44 | # timestamp => Time::HiRes::time(), | |||||
| 45 | # severity_text => $level, | |||||
| 46 | # severity_number => $OTEL_SEVERITY{$level}, | |||||
| 47 | # body => $str, | |||||
| 48 | # attributes => $self->{ctx} ? { ctx => $self->{ctx} } : {}, | |||||
| 49 | # ); | |||||
| 50 | # - Map internal levels: trace=1, debug=5, info=9, notice=10, | |||||
| 51 | # warn=13, error=17 (OTel SeverityNumber spec, table 5). | |||||
| 52 | # - Store the provider reference, not a cached Logger, to survive | |||||
| 53 | # provider swaps (workaround for blocker 3 above). | |||||
| 54 | ||||||
| 55 | # Enforce strict variable declarations and enable common warnings | |||||
| 56 | 39 39 39 | 1655837 25 206 | use strict; | |||
| 57 | 39 39 39 | 53 22 518 | use warnings; | |||
| 58 | ||||||
| 59 | # Automatically throw exceptions on failed built-ins (open, close, socket, | |||||
| 60 | # send...). Not ':all': that adds system()/exec(), which this module never | |||||
| 61 | # calls, and which would make IPC::System::Simple a hidden dependency | |||||
| 62 | 39 39 39 | 4639 150069 47 | use autodie qw(:default); | |||
| 63 | ||||||
| 64 | # Core and CPAN dependencies. Functions are called by their full names | |||||
| 65 | # and nothing is imported, so that they can't be called as methods on a | |||||
| 66 | # logger ($log->croak, $log->syslog ...). Readonly::Values::Syslog only | |||||
| 67 | # exports variables (%syslog_values, $DEBUG ...) | |||||
| 68 | 39 39 39 | 61092 24 186 | use Carp (); | |||
| 69 | 39 39 39 | 3301 30840 311 | use IO::Handle (); | |||
| 70 | 39 39 39 | 10040 817193 568 | use Config::Abstraction 0.40; | |||
| 71 | 39 39 39 | 96 146 426 | use Params::Get 0.15; | |||
| 72 | 39 39 39 | 61 24 124 | use POSIX (); | |||
| 73 | 39 39 39 | 34 17 162 | use Readonly (); | |||
| 74 | 39 39 38 | 6066 31191 1817 | use Readonly::Values::Syslog 0.04; | |||
| 75 | 38 38 38 | 4732 7318 388 | use Return::Set 0.04; | |||
| 76 | 38 38 38 | 43 17 116 | use Scalar::Util (); | |||
| 77 | 38 38 38 | 1429 3651 145 | use Time::HiRes (); | |||
| 78 | 38 38 38 | 5373 17583 369 | use Time::Local (); | |||
| 79 | ||||||
| 80 | # Sub::Private in enforce mode: _-prefixed subs decorated :Private croak when | |||||
| 81 | # called from outside this package. HARNESS_ACTIVE bypasses checks during | |||||
| 82 | # make test so white-box tests can still reach private methods. 0.06 also | |||||
| 83 | # enforces when this module is loaded at run time (require, Log::Any). The | |||||
| 84 | # mode is set for this package only (0.07), not in $Sub::Private::config, | |||||
| 85 | # which would change it for every other module using Sub::Private. | |||||
| 86 | 38 38 37 | 5859 233223 94 | use Sub::Private 0.07 { mode => 'enforce' }; | |||
| 87 | ||||||
| 88 | # The backends, one object per destination, built by new() (see | |||||
| 89 | # _build_backends). Loaded now rather than on demand, so that they are | |||||
| 90 | # compiled with the rest of the module | |||||
| 91 | 37 37 37 | 6951 33 232 | use Log::Abstraction::Backend; | |||
| 92 | 37 37 37 | 2863 31 190 | use Log::Abstraction::Backend::Array; | |||
| 93 | 37 37 37 | 2655 37 190 | use Log::Abstraction::Backend::Code; | |||
| 94 | 37 37 37 | 2549 29 160 | use Log::Abstraction::Backend::Fd; | |||
| 95 | 37 37 37 | 2598 25 164 | use Log::Abstraction::Backend::File; | |||
| 96 | 37 37 37 | 3005 34 271 | use Log::Abstraction::Backend::Journald; | |||
| 97 | 37 37 37 | 3661 30 244 | use Log::Abstraction::Backend::LogAny; | |||
| 98 | 37 37 37 | 3085 39 209 | use Log::Abstraction::Backend::LogDispatch; | |||
| 99 | 37 37 37 | 2832 26 208 | use Log::Abstraction::Backend::Object; | |||
| 100 | 37 37 37 | 2802 24 176 | use Log::Abstraction::Backend::Sendmail; | |||
| 101 | 37 37 37 | 2834 36 29231 | use Log::Abstraction::Backend::Syslog; | |||
| 102 | ||||||
| 103 | # --------------------------------------------------------------------------- | |||||
| 104 | # Module-level constants -- no magic strings or numbers anywhere below | |||||
| 105 | # --------------------------------------------------------------------------- | |||||
| 106 | ||||||
| 107 | # Default minimum log level when none is specified in new() | |||||
| 108 | Readonly::Scalar my $DEFAULT_LEVEL => 'warning'; | |||||
| 109 | ||||||
| 110 | # Default SMTP delivery parameters for the sendmail backend | |||||
| 111 | Readonly::Scalar my $DEFAULT_SMTP_HOST => 'localhost'; | |||||
| 112 | Readonly::Scalar my $DEFAULT_SMTP_PORT => 25; | |||||
| 113 | Readonly::Scalar my $DEFAULT_FROM_ADDR => 'noreply@localhost'; | |||||
| 114 | Readonly::Scalar my $MIN_PORT => 1; | |||||
| 115 | Readonly::Scalar my $MAX_PORT => 65535; | |||||
| 116 | ||||||
| 117 | # Default strftime pattern for %timestamp% and the JSON timestamp | |||||
| 118 | Readonly::Scalar my $DEFAULT_TIMESTAMP_FORMAT => '%Y-%m-%d %H:%M:%S'; | |||||
| 119 | ||||||
| 120 | # strftime pattern for timestamp_format => 'iso8601' or 'rfc3339', without | |||||
| 121 | # the offset, which is 'Z' in UTC and '%:z' otherwise | |||||
| 122 | Readonly::Scalar my $RFC3339_TIMESTAMP_FORMAT => '%Y-%m-%dT%H:%M:%S'; | |||||
| 123 | ||||||
| 124 | # Most digits of fractional seconds (nanoseconds); a %N without a width | |||||
| 125 | # gives this many | |||||
| 126 | Readonly::Scalar my $MAX_TIMESTAMP_PRECISION => 9; | |||||
| 127 | ||||||
| 128 | # Number of rotated files kept (FILE.1 ... FILE.5) when rotate_keep isn't given | |||||
| 129 | Readonly::Scalar my $DEFAULT_ROTATE_KEEP => 5; | |||||
| 130 | ||||||
| 131 | # Seconds after which an open log file is closed and opened again, when | |||||
| 132 | # reopen_interval isn't given, in case a rotation tool doesn't send SIGHUP | |||||
| 133 | Readonly::Scalar my $DEFAULT_REOPEN_INTERVAL => 300; | |||||
| 134 | ||||||
| 135 | # reopen_interval values that aren't a number of seconds | |||||
| 136 | Readonly::Scalar my $REOPEN_EVERY_WRITE => 0; # close after every line | |||||
| 137 | Readonly::Scalar my $REOPEN_ON_SIGHUP => -1; # only when told to | |||||
| 138 | ||||||
| 139 | # Multipliers for the K/M/G suffixes of rotate_size | |||||
| 140 | Readonly::Hash my %SIZE_UNITS => ( | |||||
| 141 | '' => 1, | |||||
| 142 | 'k' => 1024, | |||||
| 143 | 'm' => 1024 ** 2, | |||||
| 144 | 'g' => 1024 ** 3, | |||||
| 145 | ); | |||||
| 146 | ||||||
| 147 | # rotate_interval names, each mapped to a function of (epoch seconds, UTC | |||||
| 148 | # offset in seconds, use UTC?) that returns the period it falls in. The file | |||||
| 149 | # rotates when its last-modified time is in an earlier period than now. | |||||
| 150 | # Weeks start on Monday: day 0 (1970-01-01) was a Thursday | |||||
| 151 | Readonly::Hash my %ROTATE_PERIOD => ( | |||||
| 152 | hourly => sub { int(($_[0] + $_[1]) / 3600) }, | |||||
| 153 | daily => sub { int(($_[0] + $_[1]) / 86_400) }, | |||||
| 154 | weekly => sub { int((int(($_[0] + $_[1]) / 86_400) + 3) / 7) }, | |||||
| 155 | monthly => sub { my @tm = $_[2] ? gmtime($_[0]) : localtime($_[0]); ($tm[5] * 12) + $tm[4] }, | |||||
| 156 | ); | |||||
| 157 | ||||||
| 158 | # Default log-line format tokens for file/fd/scalar-path backends | |||||
| 159 | Readonly::Scalar my $DEFAULT_FORMAT => '%level%> [%timestamp%] %class% %callstack% %message%'; | |||||
| 160 | Readonly::Scalar my $DEFAULT_FORMAT_NOCLASS => '%level%> [%timestamp%] %callstack% %message%'; | |||||
| 161 | ||||||
| 162 | # The backend class for each key of a logger hash, in the order they are | |||||
| 163 | # given a message | |||||
| 164 | Readonly::Array my @HASH_BACKENDS => qw(file array sendmail syslog journald log_any log_dispatch fd); | |||||
| 165 | Readonly::Hash my %BACKEND_CLASS => ( | |||||
| 166 | array => 'Log::Abstraction::Backend::Array', | |||||
| 167 | fd => 'Log::Abstraction::Backend::Fd', | |||||
| 168 | file => 'Log::Abstraction::Backend::File', | |||||
| 169 | journald => 'Log::Abstraction::Backend::Journald', | |||||
| 170 | log_any => 'Log::Abstraction::Backend::LogAny', | |||||
| 171 | log_dispatch => 'Log::Abstraction::Backend::LogDispatch', | |||||
| 172 | sendmail => 'Log::Abstraction::Backend::Sendmail', | |||||
| 173 | syslog => 'Log::Abstraction::Backend::Syslog', | |||||
| 174 | ); | |||||
| 175 | ||||||
| 176 | # Regex: characters forbidden in a log-file path (prevents command injection). | |||||
| 177 | # Anchored with \z, not $, which would accept a trailing newline | |||||
| 178 | Readonly::Scalar my $RE_SAFE_PATH => qr/^([^<>|*?;!`\$"\x00-\x1F]+)\z/; | |||||
| 179 | ||||||
| 180 | # Regex: path component that would escape the intended directory | |||||
| 181 | Readonly::Scalar my $RE_DOTDOT => qr/\.\./; | |||||
| 182 | ||||||
| 183 | # Regex: characters forbidden in an SMTP hostname (allows a-z, A-Z, 0-9, dot, hyphen) | |||||
| 184 | Readonly::Scalar my $RE_SAFE_HOST => qr/[^a-zA-Z0-9.\-]/; | |||||
| 185 | ||||||
| 186 | # Regex: a valid TCP port number string (decimal digits only; range checked separately) | |||||
| 187 | Readonly::Scalar my $RE_PORT => qr/^\d+$/; | |||||
| 188 | ||||||
| 189 | # Regex: a valid journald field name (uppercase ASCII, digits and underscore, | |||||
| 190 | # not starting with an underscore, which journald reserves for trusted fields) | |||||
| 191 | Readonly::Scalar my $RE_JOURNALD_FIELD => qr/^[A-Z0-9][A-Z0-9_]*$/; | |||||
| 192 | ||||||
| 193 | # Most messages a sendmail digest holds, unless digest_max says otherwise; | |||||
| 194 | # beyond it they are only counted | |||||
| 195 | Readonly::Scalar my $DEFAULT_DIGEST_MAX => 100; | |||||
| 196 | ||||||
| 197 | # Exit status of an async sendmail child (see _send_email) | |||||
| 198 | Readonly::Scalar my $EXIT_SENT => 0; | |||||
| 199 | Readonly::Scalar my $EXIT_FAILED => 1; | |||||
| 200 | ||||||
| 201 | # What each match of a redact pattern is replaced with | |||||
| 202 | Readonly::Scalar my $REDACTED_MARKER => '[REDACTED]'; | |||||
| 203 | ||||||
| 204 | # Single JSON encoder for format => 'json', built on first use. It returns | |||||
| 205 | # a character string so that all backends share one output-encoding path | |||||
| 206 | my $json_encoder; | |||||
| 207 | ||||||
| 208 | # How many SIGHUP signals the process has had. Each open log file remembers the | |||||
| 209 | # count when it was opened, and is opened again on the next write once the | |||||
| 210 | # count has changed. The handler only counts: closing a handle there could | |||||
| 211 | # close it between _file_handle returning it and the print | |||||
| 212 | my $sighup_count = 0; | |||||
| 213 | ||||||
| 214 | # The SIGHUP handler that _catch_sighup installed, if it is installed; the | |||||
| 215 | # $SIG{HUP} it replaced, put back by _release_sighup; and how many loggers | |||||
| 216 | # use it (each has _sighup set) | |||||
| 217 | my $sighup_handler; | |||||
| 218 | my $sighup_previous; | |||||
| 219 | my $sighup_users = 0; | |||||
| 220 | ||||||
| 221 | # Process IDs of the children sending emails for sendmail's async option, | |||||
| 222 | # not yet reaped (by _reap_email_children) | |||||
| 223 | my @email_children; | |||||
| 224 | ||||||
| 225 - 233 | =head1 NAME Log::Abstraction - Logging Abstraction Layer =head1 VERSION 0.41 =cut | |||||
| 234 | ||||||
| 235 | our $VERSION = '0.41'; | |||||
| 236 | ||||||
| 237 - 1002 | =head1 SYNOPSIS
use Log::Abstraction;
# The default level is 'warning'; 'trace' lets every example through
my $logger = Log::Abstraction->new(logger => 'logfile.log', level => 'trace');
$logger->debug('This is a debug message');
$logger->info('This is an info message');
$logger->notice('This is a notice message');
$logger->trace('This is a trace message');
$logger->warn({ warning => 'This is a warning message' });
# Structured fields
$logger->info('User logged in', { user_id => 42 });
=head1 DESCRIPTION
The C<Log::Abstraction> class provides a flexible logging layer on top of
different types of loggers, including code references, arrays, file paths,
and objects. It also supports logging to syslog if configured.
=head2 Unicode
Messages may be character strings containing any Unicode text. The file,
fd and scalar-path backends write character strings as UTF-8 (unless an
C<fd> handle already has a C<:utf8> or C<:encoding> layer, in which case the
handle does the encoding), and C<format =E<gt> 'json'> output is UTF-8 too.
journald fields are sent as UTF-8. Byte strings are written unchanged.
=head2 Structured fields
Every logging method accepts a hash reference of structured fields after
the message:
$logger->info('User logged in', { user_id => 42, ip => $ip });
$logger->warn('Slow query', { ms => 1250 });
A hash reference is taken as fields only when it is the last of two or more
arguments, so C<warn({ warning =E<gt> ... })> keeps its meaning, and a lone
hash reference is still a message. An empty hash reference is ignored. The
fields are copied, so changing the hash afterwards doesn't change what was
logged. They are kept out of the message and go to each backend as follows:
=over 4
=item * L</messages>, C<array> and an ARRAY C<logger> -- a C<fields> key in
the entry, alongside C<level> and C<message>.
=item * a CODE C<logger> -- a C<fields> key in the hashref it is called with.
=item * C<format =E<gt> 'json'> -- a nested C<fields> object. Objects are
stringified; other references are kept as JSON data.
=item * C<journald> -- journal fields. Each name is upper-cased, characters
other than C<A-Z>, C<0-9> and C<_> become C<_>, leading underscores are
removed and it is cut to 64 characters; a field left with no name is
dropped. Fields override the extra keys in the C<journald> hash, but never
C<MESSAGE>, C<PRIORITY> or C<SYSLOG_IDENTIFIER>.
=item * text formats (C<file>, C<fd>, a scalar C<logger>), C<syslog>,
C<sendmail> and object loggers -- appended to the message as logfmt-style
C<key=value> pairs in key order, e.g. C<User logged in ip=10.0.0.1 user_id=42>.
Characters other than C<[\w.-]> in a key become C<_>. A value that is empty
or contains white space, C<">, C<=> or C<\> is double-quoted, with C<"> and
C<\> escaped and control characters written as C<\n>, C<\r>, C<\t> or
C<\xNN>. Objects are stringified and other references written as JSON. An
object logger is passed the pairs as an extra argument after the message.
=back
When logging through L<Log::Any>, a hash reference at the end of the call,
together with the proxy's C<context>, arrives here as fields; see
L<Log::Any::Adapter::Abstraction/structured>.
=head2 Redaction
The C<redact> option removes secrets before a message reaches the history
or any backend. Each match of any of its patterns is replaced with
C<[REDACTED]>:
my $log = Log::Abstraction->new(
logger => '/var/log/myapp.log',
redact => [qr/password=\S+/, qr/\b\d{4}(?:[ -]?\d{4}){3}\b/],
);
$log->warn('Login failed: user=fred password=hunter2');
# Login failed: user=fred [REDACTED]
To keep the start of a match, end it with C<\K>: C<qr/password=\K\S+/> logs
C<password=[REDACTED]>. The patterns run over the whole message, after its
arguments are joined, so a match may span them, as in
C<$log-E<gt>info('password=', $password)>; a CODE or object logger then gets
the joined message as one argument. The text given to C<carp> or C<croak>
(see L</warn> and L</error>) is redacted too.
L</Structured fields> are redacted as well: string values, including those
inside plain hashes and arrays, and objects whose stringification matches
(they become the redacted string). Field names aren't redacted, nor are
the format string, C<%env_*%> values or C<ctx>.
Redaction is applied only to messages that pass the logger's C<level>, so
it costs nothing for messages that are dropped. A pattern that can match
the empty string, such as C<qr/x*/>, is rejected by L</new>.
=head2 Email digests
C<min_interval> limits the C<sendmail> backend to one email per interval,
dropping the messages in between. With C<digest>, they are held instead,
and sent ahead of the next message in the first email after the interval:
my $log = Log::Abstraction->new(
logger => {
file => '/var/log/myapp.log',
sendmail => {
to => 'ops@example.com',
level => 'error',
min_interval => 300,
digest => 1,
format => '%level%> [%timestamp%] %message%',
},
},
);
Each message is one line of the email, oldest first, as its own email body
would be: formatted with the C<sendmail> C<format> if there is one (as
above, so that each line has its time), else the message. At most
C<digest_max> messages (default 100) are held; later ones are only
counted, and the email says C<... and N more messages> after the held ones.
Messages held when an email fails to send stay held, and the new one is
held with them.
Nothing is sent on a timer: held messages go out with the next email,
when L</flush> is called, or when the logger is destroyed (which calls
L</flush>). A clone made with L</new> starts with none held.
=head2 Per-backend level and format
Every backend can have its own C<level> and C<format>, as well as the
logger's. C<syslog>, C<journald> and C<sendmail> are hashes already, so
they take them as keys. C<file>, C<fd> and C<array>, inside a C<logger> hash
or at the top level, and C<log_any> and C<log_dispatch>, may be given as a
hash holding the destination under the backend's own name:
my $log = Log::Abstraction->new(
level => 'debug',
logger => {
file => { file => '/var/log/myapp.log', format => 'json' },
fd => { fd => \*STDERR, level => 'warning' },
array => { array => \@recent, level => 'info' },
syslog => { level => 'error', format => '%level%: %message%' },
},
);
=over 4
=item * C<level> -- the backend only gets messages at this level or more
severe. A level name or a syslog number (0-7). The logger's C<level> is
applied first, so a backend's level can only narrow it: set the logger's
C<level> to the most verbose any backend wants.
=item * C<format> -- a format string, or C<json>, as for the logger's
L</format>, which it overrides. For C<file> and C<fd> it is the line
written. For the others, which by default get the message as it is, it
replaces the message: the C<array> entry's C<message>, the text sent to
syslog, Log::Any or Log::Dispatch, the journal's C<MESSAGE> field and the
email body.
=back
The plain forms (C<file =E<gt> $path>, C<fd =E<gt> $handle>,
C<array =E<gt> \@array>, C<log_any =E<gt> $category>,
C<log_dispatch =E<gt> $dispatcher>) still work and have no level or format of their
own. A blessed handle object is a destination, not the hash form.
=head2 Forwarding to Log::Any and Log::Dispatch
L<Log::Any::Adapter::Abstraction> brings messages from L<Log::Any> into
C<Log::Abstraction>. The C<log_any> and C<log_dispatch> backends go the
other way, sending messages on to an application's existing L<Log::Any> or
L<Log::Dispatch> set-up, alongside any other backends:
my $log = Log::Abstraction->new(
level => 'debug',
logger => {
log_any => 'MyApp', # a category, or a Log::Any logger
log_dispatch => $dispatcher, # a Log::Dispatch object
file => '/var/log/myapp.log',
},
);
Levels keep their names, except that C<warn> becomes C<warning>, and
Log::Dispatch, which has nothing below C<debug>, gets C<trace> messages as
C<debug>. Log::Any gets L</Structured fields> as its trailing hashref, so a
structured adapter receives them as data; Log::Dispatch has no fields, so
they are appended to the message as text. With its own C<format> (see
L</Per-backend level and format>) a backend gets the formatted line instead.
A C<Log::Any> category name is looked up with
C<Log::Any-E<gt>get_logger(category =E<gt> $name)> (which needs L<Log::Any>
installed) when the first message is sent, and follows later
C<Log::Any::Adapter-E<gt>set()> calls. If Log::Any or Log::Dispatch dies,
C<Carp::carp> is called and the other backends still get the message.
A C<Log::Any::Proxy> or C<Log::Dispatch> object given as the C<logger>
itself is used in the same way, rather than as an object whose method is
called for each level: neither has a method for every level, and both
would join the arguments with spaces.
A message that reaches a C<Log::Abstraction> while it is being forwarded
(e.g. through L<Log::Any::Adapter::Abstraction>) is logged by that logger's
other backends but not forwarded again, so a set-up that points back at
itself doesn't loop.
=head2 File rotation
Log files written by path (a scalar C<logger>, a C<file> key in a C<logger>
hash, and the top-level C<file>) can be rotated by size, by time, or both:
my $log = Log::Abstraction->new(
file => '/var/log/myapp.log',
rotate_size => '10M',
rotate_interval => 'daily',
rotate_keep => 7,
);
Before each write the file is checked, and if it is due it is renamed to
F<myapp.log.1>, the old F<.1> to F<.2> and so on, the oldest beyond
C<rotate_keep> being deleted; the line then goes to a new F<myapp.log>. A
rotation that fails (e.g. for lack of permission) is ignored, and the line is
still written. File handles passed as C<fd> aren't rotated.
Rotation isn't coordinated between processes: if several processes log to the
same file, use B<logrotate> instead.
=head3 logrotate
The file is kept open between messages, but before each write the logger
checks that the path still names the same file (device and inode), so
B<logrotate>'s default (rename the file and let the application create a new
one) works without C<copytruncate>, and without sending the process a
C<SIGHUP>: the next message is written to a new file.
A C<postrotate> script that sends the process a C<SIGHUP> works too: except
on Windows, the first time a logger opens a file, C<Log::Abstraction> sets
C<$SIG{HUP}> to a handler that makes every logger open its files again on
the next write. A handler that was already set (a code reference or a sub
name) is called after it. This means a C<SIGHUP> no longer ends the
program, as it does by default, while a logger that has opened a file
exists. When the last of them is destroyed, the handler that was there
before is put back. A handler that the program sets later replaces
C<Log::Abstraction>'s (and isn't changed when the loggers are destroyed);
it can call L</reopen> itself.
In case a C<SIGHUP> isn't sent, every file is also closed and opened again
every 5 minutes, by default. C<reopen_interval> changes how often, makes
C<SIGHUP> the only way (C<-1>), or closes the file after every message
(C<0>), as before version 0.40.
On Windows an open file can't be renamed or deleted, so a file the logger is
writing can only be rotated by the logger itself (which closes it first), or
after calling L</reopen>, and then only until the next message.
=head1 METHODS
=head2 new
my $logger = Log::Abstraction->new(%args);
my $logger = Log::Abstraction->new(\%args);
my $logger = Log::Abstraction->new($file_path);
# Clone with optional overrides
my $clone = $logger->new(level => 'debug');
Creates a new C<Log::Abstraction> instance, or clones an existing one when
called on an object. It may also be called as a plain function,
C<Log::Abstraction::new(%args)>, which behaves like
C<Log::Abstraction-E<gt>new(%args)>.
=head3 Arguments
=over 4
=item * C<carp_on_warn>
If set to 1, and no C<logger> is given, call C<Carp::carp> on C<warn()>.
Also causes C<error()> to C<carp> if C<croak_on_error> is not set.
=item * C<croak_on_error>
If set to 1, and no C<logger> is given, call C<Carp::croak> on C<error()>.
=item * C<config_file>
Path to a configuration file (YAML, XML, INI, etc.) whose contents are
merged with the constructor arguments. On non-Windows systems the class
can also be configured via environment variables prefixed with
C<"Log::Abstraction::">. For example:
export Log::Abstraction::script_name=foo
=item * C<ctx>
Arbitrary context value passed through to CODE-ref logger callbacks as
C<$args-E<gt>{ctx}>.
=item * C<format>
Format string for the file, fd and scalar-path backends; a backend's own
C<format> (see L</Per-backend level and format>) overrides it for that
backend. Unset or an empty string means the default,
C<%level%E<gt> [%timestamp%] %class% %callstack% %message%>. Tokens expanded
at log time:
%callstack% caller file and line number
%class% blessed class of the logger object
%level% upper-cased level name
%message% the joined log message
%timestamp% the time of the call; YYYY-MM-DD HH:MM:SS local time by
default (see timestamp_format, timestamp_precision and utc)
%env_FOO% value of $ENV{FOO}, or empty string if unset
Tokens are only expanded in the format string itself, never in the text
of the message. Each line break in a message is followed by a tab, so a
continuation line can't be mistaken for a new log entry.
The special value C<"json"> (not a format string but a magic keyword) switches
all file and fd backends to emit one compact JSON object per log line:
{"timestamp":"...","level":"info","message":"...","file":"...","line":42}
This format is compatible with log aggregators such as journald, Loki,
Elasticsearch, and Splunk. C<class> is included when the logger is a subclass
of C<Log::Abstraction>, and C<fields> when the call has L</Structured fields>.
Keys are emitted in sorted order.
B<Security note:> because a format may contain C<%env_*%> tokens, which
expand to environment variables, avoid granting untrusted sources write
access to config files that set C<format> or any backend's C<format> (see
L</Per-backend level and format>).
=item * C<level>
Minimum level at which to emit log entries. Defaults to C<"warning">.
Valid values (case-insensitive): C<trace>, C<debug>, C<info>/C<informational>,
C<notice>, C<warn>/C<warning>, C<error>/C<err>, C<crit>/C<critical>/C<fatal>,
C<alert>, C<emerg>/C<emergency>/C<panic>. C<trace> and C<debug> are the same
threshold (see L</LIMITATIONS>). It may also be an array reference, whose
first element is used, as some configuration-file formats produce.
=item * C<max_messages>
The most entries to keep in the in-memory history returned by
L</messages>; when it is full, the oldest entry is discarded. Must be a
non-negative integer; C<0> keeps no history at all. Unlimited by default, which in a long-running process
means the history grows without bound.
=item * C<logger>
One of:
=over 4
=item * A code reference -- called with a hashref C<{ class, file, line, level, message, ctx, fields }>
(C<ctx> and C<fields> only when there are any)
=item * An object -- method matching the level name is called on it; a
L<Log::Any> logger or a L<Log::Dispatch> object is used as the C<log_any> or
C<log_dispatch> backend (see L</Forwarding to Log::Any and Log::Dispatch>)
=item * A hash reference -- may contain C<file>, C<array>, C<fd>, C<syslog>, C<journald>, C<sendmail>,
C<log_any> and/or C<log_dispatch> keys,
each of which may have its own C<level> and C<format> (see L</Per-backend level and format>)
=item * An array reference -- C<{ level, message }> hashrefs are pushed onto it, with a
C<fields> key when the call has L</Structured fields>
=item * A scalar string -- treated as a file path to append to
=back
When not supplied, L<Log::Log4perl> is initialised as the default backend.
The C<sendmail> sub-hash supports:
C<host>, C<port>, C<to>, C<from>, C<subject>, C<level>, C<format>,
C<min_interval>, C<digest>, C<digest_max>, C<async>. C<to> is required. With C<format>, the email body is the
formatted line rather than the message. C<level> may be a level name or a syslog number (0-7);
without it, every message is emailed.
At most one email is sent per C<min_interval> seconds per instance; the
messages in between are dropped, unless C<digest> is set, which sends them
with the next email (see L</Email digests>). If delivery fails,
C<Carp::carp> is called and the other backends still receive the message.
Sending an email waits for the SMTP server, which can take seconds. With
C<async =E<gt> 1>, the email is sent by a child process (made with
C<fork>), and the log call returns at once. The C<host> and C<port> are
still checked first. The logger can't know whether the child succeeded:
the child carps a failure itself, and the message (and any digest sent
with it) is lost rather than held. Emails sent close together are sent at
the same time, so they may arrive in any order. The finished children are
reaped the next time an email is sent and when a logger is destroyed; a program that
reaps every child itself (e.g. C<waitpid(-1, ...)> in a C<$SIG{CHLD}>
handler) may see them. On Windows, whose C<fork> is emulated with threads,
when C<fork> fails, and for the email sent when perl exits, the email is
sent in the log call as without C<async>.
The C<syslog> sub-hash supports the keys below. The message is passed to
C<syslog()> through a C<%s> format, so C<%> sequences in it, such as C<%m>,
are logged literally.
=over 4
=item * C<facility> -- the syslog facility (default: C<local0>)
=item * C<level> -- only messages at this level or more severe are sent; a level name or a syslog number (0-7)
=item * C<format> -- format the message with this (see L</format>) before sending it; by default the message is sent as it is
=item * C<host> (or its alias C<server>), and any other L<Sys::Syslog/setlogsock> option -- passed to C<setlogsock()>
=back
The C<journald> sub-hash sends each message as a single datagram to the
systemd journal using the journald native protocol. Supported keys:
=over 4
=item * C<socket> -- path to the journald socket (default: F</run/systemd/journal/socket>)
=item * C<identifier> -- value for the C<SYSLOG_IDENTIFIER> field (default: basename of C<$0>)
=item * C<level> -- only messages at this level or more severe are sent; a level name or a syslog number (0-7)
=item * C<format> -- the C<MESSAGE> field is the message formatted with this (see L</format>); by default it is the message as it is
=item * any other key -- included verbatim as an uppercase journald field name.
The upper-cased name must contain only C<A-Z>, C<0-9> and C<_>, and must not
start with C<_>; C<new()> croaks otherwise.
=back
The C<PRIORITY> field is set automatically from the log level (0=emerg...7=debug).
A message too large for one datagram (about 200KB) is truncated and
C<[truncated]> appended.
Delivery failures are silent apart from a single C<Carp::carp> (repeated only
after a later send has succeeded); the application is never crashed by a
journald error. The socket is opened for the first message and reused for
the next ones; after a failed send it is closed, and the next message opens a
new one. Each datagram is addressed to the socket path, so delivery
continues after journald restarts.
=item * C<redact>
Patterns to remove from every message before it is logged: a C<qr//>, a
string (compiled as a regular expression; a config file can't hold a
C<qr//>), or an array reference of them. See L</Redaction>.
=item * C<reopen_interval>
Log files written by path are kept open between messages. Every this many
seconds (default 300, i.e. 5 minutes) each one is closed and opened again on
its next write, in case a rotation tool changed the file without renaming it
and without sending a C<SIGHUP> (see L</logrotate>).
C<0> closes the file after every message, so it is never held open, and no
C<SIGHUP> handler is installed for it. C<-1> never reopens the file because
of time: only a C<SIGHUP>, L</reopen>, or the file being renamed or deleted
does. (Windows has no C<SIGHUP>.)
=item * C<rotate_interval>
Rotate log files by time: C<hourly>, C<daily>, C<weekly> (weeks start on
Monday) or C<monthly>, case-insensitive. Before each write, a file whose
last-modified time is in an earlier period than now (in local time, or UTC
with C<utc>) is rotated, so a file not written to for a while rotates on the
next write. See L</File rotation>.
=item * C<rotate_keep>
How many rotated files to keep, F<FILE.1> to F<FILE.I<n>> (default 5). With
C<0>, a file due for rotation is deleted instead.
=item * C<rotate_size>
Rotate log files that have reached this size: a number of bytes, optionally
followed by C<K>, C<M> or C<G> (powers of 1024), e.g. C<10M>. See
L</File rotation>.
=item * C<script_name>
Script name reported to syslog. Auto-detected from C<$0> if not supplied.
=item * C<timestamp_format>
How C<%timestamp%>, and the C<timestamp> key of C<format =E<gt> 'json'>,
are written. Either a L<POSIX/strftime> pattern (default
C<%Y-%m-%d %H:%M:%S>) or one of these names (case-insensitive):
iso8601, rfc3339 2026-10-03T20:14:23-04:00, or 2026-10-04T00:14:23Z with utc
The pattern may also use:
%N fractional seconds, 9 digits (nanoseconds)
%3N fractional seconds, 3 digits (milliseconds); any width 1-9
%z UTC offset as +hhmm (on every platform, unlike some strftimes)
%:z UTC offset as +hh:mm, as RFC 3339 needs
%Z the time-zone name; "UTC" when utc is set
%% a literal %
Fractional seconds come from L<Time::HiRes> and are truncated, not rounded;
digits beyond the system clock's resolution (usually microseconds) are
noise. The timestamp is taken once per message, so every backend shows the
same time.
=item * C<timestamp_precision>
The number of fractional-second digits, 0-9 (default 0), added after the
seconds (each C<%S>) of whichever C<timestamp_format> is in use:
Log::Abstraction->new(timestamp_format => 'rfc3339', timestamp_precision => 3, utc => 1);
# 2026-10-04T00:14:24.094Z
=item * C<utc>
If true, timestamps are in UTC rather than local time.
=item * C<verbose>
When using the default Log::Log4perl backend, raises the logging level to
DEBUG when set to a true value.
=back
=head3 Returns
A blessed C<Log::Abstraction> object.
=head3 Side Effects
Loads C<File::Basename> if C<syslog> is configured (either at the top level
or in a C<logger> hash) and C<script_name> is not supplied. Loads
C<Log::Log4perl> if no backend (C<logger>, C<file>, C<fd> or C<array>) is
specified.
Builds one L<Log::Abstraction::Backend> object for each place messages go
to. The arguments are not changed: in particular, the C<syslog> hash keeps
its C<facility>, C<level> and C<format> keys, and a C<server> key is not
renamed C<host> (before 0.40, the first message did both).
=head3 Example
my $logger = Log::Abstraction->new(
level => 'debug',
logger => \@messages,
);
my $clone = $logger->new(level => 'info');
=head3 API SPECIFICATION
=head4 Input
{
carp_on_warn => { type => 'boolean', optional => 1 },
config_file => { type => 'string', optional => 1 },
croak_on_error => { type => 'boolean', optional => 1 },
ctx => { optional => 1 },
format => { type => 'string', optional => 1 },
level => { type => 'string', regex => qr/^(trace|debug|info(?:rmational)?|notice|warn(?:ing)?|err(?:or)?|crit(?:ical)?|fatal|alert|emerg(?:ency)?|panic)$/i, optional => 1 },
logger => { optional => 1 },
max_messages => { type => 'integer', min => 0, optional => 1 },
redact => { optional => 1 }, # regex, string, or arrayref of them
reopen_interval => { type => 'integer', min => -1, optional => 1 },
rotate_interval => { type => 'string', regex => qr/^(hourly|daily|weekly|monthly)$/i, optional => 1 },
rotate_keep => { type => 'integer', min => 0, optional => 1 },
rotate_size => { type => 'string', regex => qr/^\s*[1-9]\d*\s*[kmg]?b?\s*$/i, optional => 1 },
script_name => { type => 'string', optional => 1 },
timestamp_format => { type => 'string', min => 1, optional => 1 },
timestamp_precision => { type => 'integer', min => 0, max => 9, optional => 1 },
utc => { type => 'boolean', optional => 1 },
verbose => { type => 'boolean', optional => 1 },
}
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=head3 MESSAGES
Error Meaning / Action
---------------------------------------- -----------------------------------------
"<class>: <path>: File not readable" config_file path exists but is unreadable.
Check file permissions.
"<class>: Can't load configuration Config::Abstraction could not parse the
from <path>" file. Check syntax and format.
"<class>: syslog needs to know the syslog backend requested but script_name
script name" could not be determined. Pass it explicitly.
"<class>: attempt to encapsulate logger => Log::Abstraction would create
Log::Abstraction as a logging class, a needless forwarding loop. Use a
that would add a needless indirection" different backend.
"<class>: invalid syslog level '<l>'" level value is not a recognised syslog
level name. Use trace/debug/info/notice/
warn/warning/error.
"<class>: max_messages must be a max_messages is negative or not a number.
non-negative integer, not '<v>'"
"<class>: rotate_size must be a rotate_size is not, e.g., 1048576, 512K,
positive number of bytes, optionally 10M or 1G.
with K, M or G, not '<v>'"
"<class>: rotate_interval must be rotate_interval is not one of those names.
hourly, daily, weekly or monthly,
not '<v>'"
"<class>: rotate_keep must be a rotate_keep is negative or not a number.
non-negative integer, not '<v>'"
"<class>: reopen_interval must be a reopen_interval is not a whole number
number of seconds, 0 or -1, not '<v>'" of seconds, 0 (close after every
message) or -1 (only on SIGHUP).
"<class>: timestamp_format must be a timestamp_format is undef, empty or a
non-empty string" reference.
"<class>: timestamp_precision must be timestamp_precision is not a whole
an integer from 0 to 9, not '<v>'" number of digits from 0 to 9.
"<class>: redact patterns must be A redact entry is a reference other than
regular expressions or non-empty a qr//, or an empty string.
strings"
"<class>: invalid redact pattern '<p>': A redact string is not a valid regular
<error>" expression.
"<class>: redact pattern <p> matches the The pattern can match nothing at all
empty string" (e.g. qr/x*/), which would put a marker
between every character.
"<class>: invalid <backend> level '<l>'" A backend's 'level' (file, fd, array,
sendmail, journald) is neither a level
name nor 0-7. (A bad syslog 'level'
gives "invalid syslog level", as above.)
"<class>: the <backend> format must be A backend's 'format' is undef, empty or
a non-empty string" a reference.
"<class>: the <backend> hash needs a The hash form of file, fd, array, log_any
'<backend>' key" or log_dispatch has no destination (e.g.
file => { level => 'info' } without a
'file' key).
"<class>: the sendmail backend needs The sendmail sub-hash has no 'to' key.
a 'to' address"
"<class>: sendmail digest_max must be a digest_max is zero, negative or not a
positive integer, not '<v>'" number.
"<class>: invalid journald field name An extra journald key, upper-cased, is not
'<k>'" [A-Z0-9_] or starts with '_'.
"<class>: the logger hash has none of The logger hash has nowhere to send
the keys array, fd, file, journald, messages. (Before 0.40, the first
log_any, log_dispatch, sendmail, message croaked "Don't know how to deal
syslog" with the <level> message".)
"<class>: the logger can't be a <TYPE> logger is a reference of an unsupported
reference" type, e.g. a SCALAR or GLOB reference.
"<class>: log_any must be a Log::Any log_any is neither a Log::Any logger
logger or a category name" (Log::Any::Proxy) nor a non-empty string.
"<class>: log_any needs Log::Any to be log_any is a category name but Log::Any
installed" can't be loaded.
"<class>: log_dispatch must be a log_dispatch is not an object with a
Log::Dispatch object" log() method.
The following are not raised by C<new()> but later, by the logging methods
(C<trace>, C<debug>, C<info>, C<notice>, C<warn>, C<error>, C<fatal>,
C<critical>, C<alert>, C<emergency>), when
a message that passes the level threshold reaches the backend concerned.
Croaks are configuration errors; delivery failures only carp, because a
logging failure must never crash the application.
Croak Meaning / Action
---------------------------------------- -----------------------------------------
"<class>: Invalid file name: <path>" A file path (logger string, 'file' key or
logger hash 'file') contains one of
< > | * ? ; ! ` $ " or a control
character, or contains '..'.
"<class>: Invalid SMTP host: <host>" The sendmail 'host' contains characters
other than A-Z a-z 0-9 . -
"<class>: Invalid SMTP port: <port>" The sendmail 'port' is not an integer in
1-65535.
"<class>: <object class> doesn't know An object logger has no method for this
how to deal with the <level> message" level. (notice falls back to info.)
Carp Meaning / Action
---------------------------------------- -----------------------------------------
"Failed to send email: <error>" SMTP delivery failed. The other backends
still receive the message.
"<class>: syslog failed: <error>" Sys::Syslog::syslog() died.
"<class>: journald send failed: <error>" The journald socket could not be reached.
Given once, then not again until a send
succeeds.
"<class>: Log::Any failed: <error>" Log::Any (or its adapter) died. The other
"<class>: Log::Dispatch failed: <error>" backends still receive the message.
=head3 PSEUDOCODE
FUNCTION new(class_or_obj, args...)
Parse args:
IF single non-hash scalar
THEN store as logger shorthand
ELSE extract named params via Params::Get
IF config_file present:
CROAK if file is not readable
Load via Config::Abstraction, merge into args (constructor args win)
Restore caller-supplied array ref that config merge would have dropped
IF called on a blessed instance (clone form):
CROAK on an invalid timestamp_format or timestamp_precision
CROAK on an invalid rotate_size, rotate_interval, rotate_keep or
reopen_interval, and normalise rotate_size to bytes
CROAK on an invalid redact pattern; compile redact to one regex
shallow-clone self merged with override args
validate and store new level integer if level given in args
copy message history list
start the clone with no held email digest, no open files, and not
counted as a user of the SIGHUP handler
count the clone as a user of an open syslog connection
build the clone's own backends
RETURN clone
IF syslog requested (top level or in a logger hash) and script_name
not supplied:
auto-detect script name via File::Basename
CROAK if still undefined
IF logger arg is a Log::Abstraction object:
CROAK (would create a needless forwarding loop)
IF no logger AND no file AND no fd AND no array:
load Log::Log4perl, easy_init at DEBUG or ERROR per verbose flag
store Log4perl logger as the backend
Normalise and validate level:
IF level is an arrayref, take first element
lc() the level string
CROAK if not in syslog_values lookup
default to $DEFAULT_LEVEL if not supplied
CROAK if max_messages is given and is not a non-negative integer
CROAK if timestamp_format is empty or not a string, or
timestamp_precision is not an integer 0-9
CROAK if rotate_size is not a positive size, rotate_interval is not
hourly/daily/weekly/monthly, or rotate_keep or reopen_interval is not
a non-negative integer; normalise rotate_size to bytes
CROAK if a redact pattern is not a regex or non-empty string, doesn't
compile, or matches the empty string; compile redact to one regex
FOR each backend (top-level file/fd/array, and the logger hash's
file/fd/array/syslog/sendmail/journald/log_any/log_dispatch):
IF log_any: CROAK unless a Log::Any::Proxy, or a category name with
Log::Any installed
IF log_dispatch: CROAK unless an object with a log() method
SKIP the rest unless given as a hash
CROAK if a file/fd/array/log_any/log_dispatch hash lacks its
destination key (its own name)
CROAK if its 'level' is not a level name or 0-7
CROAK if its 'format' is undef, empty or not a string
IF logger is a hash:
CROAK if a sendmail sub-hash has no 'to' address, or a digest_max
that isn't a positive integer
CROAK if an extra journald key is not a valid journald field name
CROAK if it has none of the backend keys
self = bless { messages => [], merged args, level => numeric } as class
self->{_backends} = _build_backends() (CROAK on an unsupported logger)
RETURN self
END FUNCTION
=cut | |||||
| 1003 | ||||||
| 1004 | sub new { | |||||
| 1005 | 1722 | 2177789 | my $class = shift; | |||
| 1006 | ||||||
| 1007 | # Accept a plain hash, a hashref, or a single scalar (file-path shorthand) | |||||
| 1008 | 1722 | 681 | my %args; | |||
| 1009 | 1722 | 1856 | if((scalar(@_) == 1) && (ref($_[0]) ne 'HASH')) { | |||
| 1010 | 7 | 8 | $args{'logger'} = shift; | |||
| 1011 | } elsif(my $params = Params::Get::get_params(undef, \@_)) { | |||||
| 1012 | 695 695 | 6260 626 | %args = %{$params}; | |||
| 1013 | } | |||||
| 1014 | ||||||
| 1015 | # Load configuration from a file when config_file is present | |||||
| 1016 | 1722 | 5510 | if(exists($args{'config_file'})) { | |||
| 1017 | 11 | 67 | if(!-r $args{'config_file'}) { | |||
| 1018 | 2 | 62 | Carp::croak("$class: ", $args{'config_file'}, ': File not readable'); | |||
| 1019 | } | |||||
| 1020 | 9 | 62 | if(my $config = Config::Abstraction->new( | |||
| 1021 | config_dirs => [''], | |||||
| 1022 | config_file => $args{'config_file'}, | |||||
| 1023 | env_prefix => "${class}::", | |||||
| 1024 | )) { | |||||
| 1025 | # Merge file config with constructor args; constructor wins | |||||
| 1026 | 9 | 14182 | $config = $config->all(); | |||
| 1027 | 9 | 82 | if($config->{$class}) { | |||
| 1028 | 2 | 1 | $config = $config->{$class}; | |||
| 1029 | } | |||||
| 1030 | 9 | 11 | my $array = $args{'array'}; | |||
| 1031 | 9 9 | 7 18 | %args = (%{$config}, %args); | |||
| 1032 | # Restore caller-supplied array ref after merge (config can't supply refs) | |||||
| 1033 | 9 | 15 | if($array) { | |||
| 1034 | 5 | 5 | $args{'array'} = $array; | |||
| 1035 | } | |||||
| 1036 | } else { | |||||
| 1037 | 0 | 0 | Carp::croak("$class: Can't load configuration from ", $args{'config_file'}); | |||
| 1038 | } | |||||
| 1039 | } | |||||
| 1040 | ||||||
| 1041 | # Handle function-call form: Log::Abstraction::new() with no class | |||||
| 1042 | 1720 | 1336 | if(!defined($class)) { | |||
| 1043 | 1 | 1 | $class = __PACKAGE__; | |||
| 1044 | } elsif(Scalar::Util::blessed($class)) { | |||||
| 1045 | # Called on an existing instance -- return a shallow clone | |||||
| 1046 | 1035 | 660 | _check_timestamp_args(ref($class), \%args); | |||
| 1047 | 1033 | 668 | _check_rotate_args(ref($class), \%args); | |||
| 1048 | 1031 | 624 | _check_redact_args(ref($class), \%args); | |||
| 1049 | 1030 1030 | 413 737 | my $clone = bless { %{$class}, %args }, ref($class); | |||
| 1050 | 1030 | 560 | if(my $level = $args{'level'}) { | |||
| 1051 | 8 | 8 | $level = lc($level); | |||
| 1052 | 8 | 13 | if(!defined($syslog_values{$level})) { | |||
| 1053 | 1 | 6 | Carp::croak("$class: invalid syslog level '$level'"); | |||
| 1054 | } | |||||
| 1055 | 7 | 7 | $clone->{level} = $syslog_values{$level}; | |||
| 1056 | } | |||||
| 1057 | # Copy the message history so parent and clone diverge independently | |||||
| 1058 | 1029 1029 | 362 447 | $clone->{messages} = [ @{$class->{messages}} ]; | |||
| 1059 | # A clone has its own digest, or held messages would be sent twice | |||||
| 1060 | 1029 1029 | 378 424 | delete @{$clone}{qw(_email_digest _email_digest_dropped)}; | |||
| 1061 | # and opens its own files, so that closing them doesn't affect the parent | |||||
| 1062 | 1029 1029 | 385 371 | delete @{$clone}{qw(_handles _sighup)}; | |||
| 1063 | # The clone shares the parent's open syslog connection | |||||
| 1064 | 1029 | 487 | Log::Abstraction::Backend::Syslog->retain_connection() if($clone->{_syslog_opened}); | |||
| 1065 | # and has its own backends, as the overrides may change them | |||||
| 1066 | 1029 | 468 | $clone->{_backends} = $clone->_build_backends(); | |||
| 1067 | 1028 | 671 | return $clone; | |||
| 1068 | } | |||||
| 1069 | ||||||
| 1070 | # Auto-detect script name when syslog backend is requested, either as a | |||||
| 1071 | # top-level key or (the documented form) inside a HASH logger | |||||
| 1072 | my $wants_syslog = $args{'syslog'} | |||||
| 1073 | 685 | 1125 | || ((ref($args{'logger'}) eq 'HASH') && $args{'logger'}->{'syslog'}); | |||
| 1074 | 685 | 551 | if($wants_syslog && !$args{'script_name'}) { | |||
| 1075 | 6 | 16 | require File::Basename; | |||
| 1076 | 6 | 182 | $args{'script_name'} = File::Basename::basename($ENV{'SCRIPT_NAME'} || $0); | |||
| 1077 | Carp::croak("$class: syslog needs to know the script name") | |||||
| 1078 | 6 | 8 | if(!defined($args{'script_name'})); | |||
| 1079 | } | |||||
| 1080 | ||||||
| 1081 | # Reject attempts to use this module as its own logger backend | |||||
| 1082 | 685 | 865 | if(defined(my $logger = $args{logger})) { | |||
| 1083 | 327 | 319 | if(Scalar::Util::blessed($logger) && (ref($logger) eq __PACKAGE__)) { | |||
| 1084 | 2 | 11 | Carp::croak( | |||
| 1085 | "$class: attempt to encapsulate ", | |||||
| 1086 | __PACKAGE__, | |||||
| 1087 | ' as a logging class, that would add a needless indirection', | |||||
| 1088 | ); | |||||
| 1089 | } | |||||
| 1090 | } elsif(!$args{'file'} && !$args{'fd'} && !$args{'array'}) { | |||||
| 1091 | # Fall back to Log::Log4perl when no other backend is configured | |||||
| 1092 | 15 | 2403 | require Log::Log4perl; | |||
| 1093 | 15 | 81331 | Log::Log4perl->import(); | |||
| 1094 | Log::Log4perl->easy_init( | |||||
| 1095 | 15 | 196 | $args{verbose} ? $Log::Log4perl::DEBUG : $Log::Log4perl::ERROR | |||
| 1096 | ); | |||||
| 1097 | 15 | 8939 | $args{'logger'} = Log::Log4perl->get_logger(); | |||
| 1098 | } | |||||
| 1099 | ||||||
| 1100 | # Resolve and store the numeric threshold for the requested level | |||||
| 1101 | 683 | 1434 | my $level = $args{'level'}; | |||
| 1102 | 683 | 428 | if($level) { | |||
| 1103 | 559 | 421 | if(ref($level) eq 'ARRAY') { | |||
| 1104 | 1 | 1 | $level = $level->[0]; | |||
| 1105 | } | |||||
| 1106 | 559 | 330 | $level = lc($level); | |||
| 1107 | 559 | 443 | if(!defined($syslog_values{$level})) { | |||
| 1108 | 3 | 20 | Carp::croak("$class: invalid syslog level '$level'"); | |||
| 1109 | } | |||||
| 1110 | 556 | 332 | $args{'level'} = $level; | |||
| 1111 | } else { | |||||
| 1112 | 124 | 86 | $args{'level'} = $DEFAULT_LEVEL; | |||
| 1113 | } | |||||
| 1114 | ||||||
| 1115 | # Cap on the in-memory message history (undef means unlimited) | |||||
| 1116 | 680 | 485 | if(defined(my $max = $args{'max_messages'})) { | |||
| 1117 | 4 | 7 | if($max !~ /^\d+$/) { | |||
| 1118 | 1 | 3 | Carp::croak("$class: max_messages must be a non-negative integer, not '$max'"); | |||
| 1119 | } | |||||
| 1120 | } | |||||
| 1121 | ||||||
| 1122 | 679 | 703 | _check_timestamp_args($class, \%args); | |||
| 1123 | 671 | 599 | _check_rotate_args($class, \%args); | |||
| 1124 | 655 | 537 | _check_redact_args($class, \%args); | |||
| 1125 | ||||||
| 1126 | # Validate the backends' own 'level' and 'format' keys now, rather than | |||||
| 1127 | # have a bad value silently drop messages at log time: the top-level | |||||
| 1128 | # file/fd/array and the HASH logger's sub-backends | |||||
| 1129 | 651 422 1953 | 410 367 1163 | my @backends = map { [ $_, $args{$_} ] } grep { defined($args{$_}) } qw(file fd array); | |||
| 1130 | 651 | 448 | if(ref($args{'logger'}) eq 'HASH') { | |||
| 1131 | 122 | 72 | my $hash = $args{'logger'}; | |||
| 1132 | 133 | 109 | push @backends, map { [ $_, $hash->{$_} ] } | |||
| 1133 | 122 976 | 120 443 | grep { defined($hash->{$_}) } qw(file fd array syslog sendmail journald log_any log_dispatch); | |||
| 1134 | } | |||||
| 1135 | 651 | 416 | for my $backend (@backends) { | |||
| 1136 | 555 555 | 230 330 | my ($name, $value) = @{$backend}; | |||
| 1137 | 555 | 347 | _check_producer($class, $name, $value) if($name =~ /^log_(?:any|dispatch)$/); | |||
| 1138 | 550 | 439 | next if(ref($value) ne 'HASH'); | |||
| 1139 | 101 | 147 | if(($name =~ /^(?:file|fd|array|log_any|log_dispatch)$/) && !$value->{$name}) { | |||
| 1140 | 7 | 25 | Carp::croak("$class: the $name hash needs a '$name' key"); | |||
| 1141 | } | |||||
| 1142 | 94 | 56 | my $sub_level = $value->{'level'}; | |||
| 1143 | 94 | 97 | if(defined($sub_level) && !defined(_level_number($sub_level))) { | |||
| 1144 | 8 | 39 | Carp::croak("$class: invalid $name level '$sub_level'"); | |||
| 1145 | } | |||||
| 1146 | 86 | 93 | if(exists($value->{'format'})) { | |||
| 1147 | 13 | 8 | my $format = $value->{'format'}; | |||
| 1148 | 13 | 34 | if(!defined($format) || ref($format) || ($format eq '')) { | |||
| 1149 | 5 | 12 | Carp::croak("$class: the $name format must be a non-empty string"); | |||
| 1150 | } | |||||
| 1151 | } | |||||
| 1152 | } | |||||
| 1153 | ||||||
| 1154 | 626 | 464 | if(ref($args{'logger'}) eq 'HASH') { | |||
| 1155 | 100 | 58 | my $hash = $args{'logger'}; | |||
| 1156 | ||||||
| 1157 | 100 | 108 | if(exists($hash->{'sendmail'}) | |||
| 1158 | && ((ref($hash->{'sendmail'}) ne 'HASH') || !$hash->{'sendmail'}->{'to'})) { | |||||
| 1159 | 1 | 2 | Carp::croak("$class: the sendmail backend needs a 'to' address"); | |||
| 1160 | } | |||||
| 1161 | 99 | 117 | if((ref($hash->{'sendmail'}) eq 'HASH') && defined(my $max = $hash->{'sendmail'}->{'digest_max'})) { | |||
| 1162 | 0 | 0 | if($max !~ /^[1-9]\d*$/) { | |||
| 1163 | 0 | 0 | Carp::croak("$class: sendmail digest_max must be a positive integer, not '$max'"); | |||
| 1164 | } | |||||
| 1165 | } | |||||
| 1166 | ||||||
| 1167 | 99 | 90 | if(ref($hash->{'journald'}) eq 'HASH') { | |||
| 1168 | 25 25 | 12 28 | for my $key (keys %{$hash->{'journald'}}) { | |||
| 1169 | 35 | 54 | next if(lc($key) =~ /^(?:socket|identifier|level|format)$/); | |||
| 1170 | 7 | 21 | if(uc($key) !~ $RE_JOURNALD_FIELD) { | |||
| 1171 | 2 | 5 | Carp::croak("$class: invalid journald field name '$key'"); | |||
| 1172 | } | |||||
| 1173 | } | |||||
| 1174 | } | |||||
| 1175 | ||||||
| 1176 | # A hash with nowhere to send messages is a mistake | |||||
| 1177 | 97 776 | 213 1426 | if(!grep { $hash->{$_} } @HASH_BACKENDS) { | |||
| 1178 | 3 | 8 | Carp::croak("$class: the logger hash has none of the keys ", join(', ', sort @HASH_BACKENDS)); | |||
| 1179 | } | |||||
| 1180 | } | |||||
| 1181 | ||||||
| 1182 | # Construct the object, and the backends that messages go to | |||||
| 1183 | my $self = bless { | |||||
| 1184 | messages => [], | |||||
| 1185 | %args, | |||||
| 1186 | 620 | 1123 | level => $syslog_values{ $args{'level'} }, | |||
| 1187 | }, $class; | |||||
| 1188 | 620 | 570 | $self->{_backends} = $self->_build_backends(); | |||
| 1189 | 618 | 885 | return $self; | |||
| 1190 | } | |||||
| 1191 | ||||||
| 1192 | # --------------------------------------------------------------------------- | |||||
| 1193 | # _build_backends -- one Log::Abstraction::Backend object per destination | |||||
| 1194 | # | |||||
| 1195 | # Purpose: Turn the logger, array, file and fd arguments into the | |||||
| 1196 | # objects that _log passes each message to, once, rather than | |||||
| 1197 | # working them out again for every message. | |||||
| 1198 | # Entry: $self -- the logger object, whose arguments new() has checked. | |||||
| 1199 | # Exit: Returns an array reference of backends, in the order they | |||||
| 1200 | # get a message: the logger (or the logger hash's file, array, | |||||
| 1201 | # sendmail, syslog, journald, log_any, log_dispatch and fd), | |||||
| 1202 | # or the top-level array if there is no logger; then the | |||||
| 1203 | # top-level file and fd. | |||||
| 1204 | # Side effects: None. The caller's hashes are not changed (the syslog | |||||
| 1205 | # backend works on a copy). | |||||
| 1206 | # Notes: Each backend's own 'level' is converted to a number here. | |||||
| 1207 | # Croaks if the logger is a reference of an unsupported type. | |||||
| 1208 | # | |||||
| 1209 | # Pseudocode: | |||||
| 1210 | # FUNCTION _build_backends(self) | |||||
| 1211 | # backends = [] | |||||
| 1212 | # IF logger is set: | |||||
| 1213 | # CODE ref -> Code | |||||
| 1214 | # ARRAY ref -> Array | |||||
| 1215 | # HASH ref -> for each key of HASH_BACKENDS that is set, its | |||||
| 1216 | # class, with destination, level and format from | |||||
| 1217 | # _backend (syslog, sendmail and journald are hashes | |||||
| 1218 | # holding level and format) | |||||
| 1219 | # plain string -> File (the path) | |||||
| 1220 | # Log::Any::Proxy -> LogAny; Log::Dispatch -> LogDispatch | |||||
| 1221 | # other object -> Object | |||||
| 1222 | # other ref -> CROAK | |||||
| 1223 | # ELSE IF array: Array | |||||
| 1224 | # IF top-level file: File; IF top-level fd: Fd | |||||
| 1225 | # RETURN backends | |||||
| 1226 | # END FUNCTION | |||||
| 1227 | # --------------------------------------------------------------------------- | |||||
| 1228 | sub _build_backends :Private { | |||||
| 1229 | my $self = shift; | |||||
| 1230 | ||||||
| 1231 | my $class = Scalar::Util::blessed($self); | |||||
| 1232 | my @backends; | |||||
| 1233 | ||||||
| 1234 | # Build one backend from a key's value: the destination under the | |||||
| 1235 | # backend's own name, plus its level (as a number) and format | |||||
| 1236 | my $build = sub { | |||||
| 1237 | my ($name, $value) = @_; | |||||
| 1238 | my ($dest, $level, $format); | |||||
| 1239 | if($name =~ /^(?:syslog|sendmail|journald)$/) { | |||||
| 1240 | # These are hashes already, holding their own level and format | |||||
| 1241 | $dest = (ref($value) eq 'HASH') ? $value : {}; | |||||
| 1242 | ($level, $format) = @{$dest}{qw(level format)}; | |||||
| 1243 | } else { | |||||
| 1244 | ($dest, $level, $format) = _backend($name, $value); | |||||
| 1245 | } | |||||
| 1246 | return $BACKEND_CLASS{$name}->new( | |||||
| 1247 | $name => $dest, | |||||
| 1248 | level => scalar(_level_number($level)), | |||||
| 1249 | format => $format, | |||||
| 1250 | ); | |||||
| 1251 | }; | |||||
| 1252 | ||||||
| 1253 | if(my $logger = $self->{'logger'}) { | |||||
| 1254 | my $type = ref($logger); | |||||
| 1255 | if($type eq 'CODE') { | |||||
| 1256 | push @backends, Log::Abstraction::Backend::Code->new(code => $logger); | |||||
| 1257 | } elsif($type eq 'ARRAY') { | |||||
| 1258 | push @backends, Log::Abstraction::Backend::Array->new(array => $logger); | |||||
| 1259 | } elsif($type eq 'HASH') { | |||||
| 1260 | push @backends, map { $build->($_, $logger->{$_}) } grep { $logger->{$_} } @HASH_BACKENDS; | |||||
| 1261 | } elsif(!$type) { | |||||
| 1262 | push @backends, Log::Abstraction::Backend::File->new(file => $logger); | |||||
| 1263 | } elsif(Scalar::Util::blessed($logger) && $logger->isa('Log::Any::Proxy')) { | |||||
| 1264 | # Neither has a method for every level, and both would join | |||||
| 1265 | # the arguments with spaces, so they aren't plain objects | |||||
| 1266 | push @backends, Log::Abstraction::Backend::LogAny->new(log_any => $logger); | |||||
| 1267 | } elsif(Scalar::Util::blessed($logger) && $logger->isa('Log::Dispatch')) { | |||||
| 1268 | push @backends, Log::Abstraction::Backend::LogDispatch->new(log_dispatch => $logger); | |||||
| 1269 | } elsif(Scalar::Util::blessed($logger)) { | |||||
| 1270 | push @backends, Log::Abstraction::Backend::Object->new(object => $logger); | |||||
| 1271 | } else { | |||||
| 1272 | Carp::croak("$class: the logger can't be a $type reference"); | |||||
| 1273 | } | |||||
| 1274 | } elsif($self->{'array'}) { | |||||
| 1275 | # A top-level array is only used when there's no logger | |||||
| 1276 | push @backends, $build->('array', $self->{'array'}); | |||||
| 1277 | } | |||||
| 1278 | ||||||
| 1279 | # Top-level file and fd keys (parallel to 'logger') | |||||
| 1280 | for my $name (qw(file fd)) { | |||||
| 1281 | push @backends, $build->($name, $self->{$name}) if($self->{$name}); | |||||
| 1282 | } | |||||
| 1283 | ||||||
| 1284 | return \@backends; | |||||
| 1285 | 37 37 37 | 85 18 579 | } | |||
| 1286 | ||||||
| 1287 | # --------------------------------------------------------------------------- | |||||
| 1288 | # _sanitize_email_header -- remove CR/LF to prevent SMTP header injection | |||||
| 1289 | # | |||||
| 1290 | # Purpose: Strip carriage-return and line-feed characters from any string | |||||
| 1291 | # that will appear in a MIME header field (To, From, Subject). | |||||
| 1292 | # Entry: $value -- a scalar, possibly containing \r, \n, or \r\n. | |||||
| 1293 | # Exit: Returns the sanitised scalar, or undef if input was undef. | |||||
| 1294 | # Notes: Called from _log before every header_set() call. | |||||
| 1295 | # --------------------------------------------------------------------------- | |||||
| 1296 | sub _sanitize_email_header :Private { | |||||
| 1297 | my ($value) = @_; | |||||
| 1298 | ||||||
| 1299 | return unless defined $value; | |||||
| 1300 | ||||||
| 1301 | # Strip all CR, LF and CRLF sequences | |||||
| 1302 | $value =~ s/\r\n?|\n//g; | |||||
| 1303 | ||||||
| 1304 | return Return::Set::set_return( | |||||
| 1305 | $value, | |||||
| 1306 | { type => 'string', 'matches' => qr/^[^\r\n]*$/ }, | |||||
| 1307 | ); | |||||
| 1308 | 37 37 37 | 8801 21 188 | } | |||
| 1309 | ||||||
| 1310 | # --------------------------------------------------------------------------- | |||||
| 1311 | # _level_number -- convert a level name or number to its numeric threshold | |||||
| 1312 | # | |||||
| 1313 | # Purpose: Let sub-backend 'level' keys (syslog, sendmail) be given | |||||
| 1314 | # either as a name ('warning', case-insensitive) or as a syslog | |||||
| 1315 | # number (0-7), and compare them consistently. | |||||
| 1316 | # Entry: $value -- a level name or an integer. | |||||
| 1317 | # Exit: Returns the integer threshold, or undef if $value is neither | |||||
| 1318 | # a recognised level name nor an integer in 0-7. | |||||
| 1319 | # Notes: A pure function (no $self), called as _level_number($value). | |||||
| 1320 | # --------------------------------------------------------------------------- | |||||
| 1321 | sub _level_number :Private { | |||||
| 1322 | my ($value) = @_; | |||||
| 1323 | ||||||
| 1324 | return unless defined $value; | |||||
| 1325 | ||||||
| 1326 | if($value =~ /^\d+$/) { | |||||
| 1327 | return ($value <= $DEBUG) ? $value + 0 : undef; | |||||
| 1328 | } | |||||
| 1329 | return $syslog_values{lc($value)}; | |||||
| 1330 | 37 37 37 | 6230 27 129 | } | |||
| 1331 | ||||||
| 1332 | # --------------------------------------------------------------------------- | |||||
| 1333 | # _backend -- split a file, fd or array backend's value into its parts | |||||
| 1334 | # | |||||
| 1335 | # Purpose: These backends take either their destination (a path, a | |||||
| 1336 | # handle, an array ref) or a hash holding the destination under | |||||
| 1337 | # the backend's own name plus optional 'level' and 'format'. | |||||
| 1338 | # Entry: $name -- 'file', 'fd' or 'array'. | |||||
| 1339 | # $value -- the configured value. | |||||
| 1340 | # Exit: Returns (destination, level, format); level and format are | |||||
| 1341 | # undef for the plain form. | |||||
| 1342 | # Notes: A pure function (no $self), called as _backend($name, $value). | |||||
| 1343 | # Only an unblessed hash is the hash form, so a handle object | |||||
| 1344 | # is still a destination. | |||||
| 1345 | # --------------------------------------------------------------------------- | |||||
| 1346 | sub _backend :Private { | |||||
| 1347 | my ($name, $value) = @_; | |||||
| 1348 | ||||||
| 1349 | return ($value, undef, undef) unless(ref($value) eq 'HASH'); | |||||
| 1350 | return ($value->{$name}, $value->{'level'}, $value->{'format'}); | |||||
| 1351 | 37 37 37 | 5309 23 114 | } | |||
| 1352 | ||||||
| 1353 | # --------------------------------------------------------------------------- | |||||
| 1354 | # _check_producer -- validate a log_any or log_dispatch backend in new() | |||||
| 1355 | # | |||||
| 1356 | # Purpose: Catch a wrong destination when the logger is built rather | |||||
| 1357 | # than at the first message. | |||||
| 1358 | # Entry: $class -- the class name, for messages. | |||||
| 1359 | # $name -- 'log_any' or 'log_dispatch'. | |||||
| 1360 | # $value -- the configured value, plain or hash form. | |||||
| 1361 | # Exit: Returns nothing; croaks on an invalid destination. | |||||
| 1362 | # Notes: A pure function (no $self). log_any takes a Log::Any::Proxy | |||||
| 1363 | # or a category name, which needs Log::Any installed; | |||||
| 1364 | # log_dispatch takes a Log::Dispatch (or anything with a | |||||
| 1365 | # Log::Dispatch-style log() method). | |||||
| 1366 | # --------------------------------------------------------------------------- | |||||
| 1367 | sub _check_producer :Private { | |||||
| 1368 | my ($class, $name, $value) = @_; | |||||
| 1369 | ||||||
| 1370 | my ($dest) = _backend($name, $value); | |||||
| 1371 | return if(!defined($dest)); # a hash form without one croaks later | |||||
| 1372 | ||||||
| 1373 | if($name eq 'log_any') { | |||||
| 1374 | if(Scalar::Util::blessed($dest)) { | |||||
| 1375 | return if($dest->isa('Log::Any::Proxy')); | |||||
| 1376 | } elsif(!ref($dest) && length($dest)) { | |||||
| 1377 | return if(eval { require Log::Any; 1 }); | |||||
| 1378 | Carp::croak("$class: log_any needs Log::Any to be installed"); | |||||
| 1379 | } | |||||
| 1380 | Carp::croak("$class: log_any must be a Log::Any logger or a category name"); | |||||
| 1381 | } | |||||
| 1382 | if(!Scalar::Util::blessed($dest) || !$dest->can('log')) { | |||||
| 1383 | Carp::croak("$class: log_dispatch must be a Log::Dispatch object"); | |||||
| 1384 | } | |||||
| 1385 | 37 37 37 | 6310 19 110 | } | |||
| 1386 | ||||||
| 1387 | # --------------------------------------------------------------------------- | |||||
| 1388 | # _to_json -- encode a data structure as a compact, canonical JSON string | |||||
| 1389 | # | |||||
| 1390 | # Purpose: One place to build and use the cached JSON::PP encoder, for | |||||
| 1391 | # format => 'json' lines and for reference-valued fields. | |||||
| 1392 | # Entry: $data -- a reference to encode. | |||||
| 1393 | # Exit: Returns a character string (not UTF-8 bytes). Falls back to | |||||
| 1394 | # Perl's stringification if the data can't be encoded (e.g. it | |||||
| 1395 | # is nested too deeply), so logging never dies. | |||||
| 1396 | # Notes: A pure function (no $self), called as _to_json($data). | |||||
| 1397 | # Blessed objects and other values JSON can't represent are | |||||
| 1398 | # encoded as null. | |||||
| 1399 | # --------------------------------------------------------------------------- | |||||
| 1400 | sub _to_json :Private { | |||||
| 1401 | my ($data) = @_; | |||||
| 1402 | ||||||
| 1403 | require JSON::PP; | |||||
| 1404 | $json_encoder ||= JSON::PP->new->canonical(1)->allow_blessed(1)->allow_unknown(1); | |||||
| 1405 | my $json = eval { $json_encoder->encode($data) }; | |||||
| 1406 | return $json // "$data"; | |||||
| 1407 | 37 37 37 | 5413 20 106 | } | |||
| 1408 | ||||||
| 1409 | # --------------------------------------------------------------------------- | |||||
| 1410 | # _field_string -- turn one structured-field value into a plain string | |||||
| 1411 | # | |||||
| 1412 | # Purpose: Text backends and journald need a string for each field. | |||||
| 1413 | # Entry: $value -- the field value: a scalar, an object, or a reference. | |||||
| 1414 | # Exit: Returns '' for undef, the stringified object for a blessed | |||||
| 1415 | # value (so overloaded stringification is honoured), JSON for | |||||
| 1416 | # any other reference, and the value itself otherwise. | |||||
| 1417 | # Notes: A pure function (no $self), called as _field_string($value). | |||||
| 1418 | # --------------------------------------------------------------------------- | |||||
| 1419 | sub _field_string :Private { | |||||
| 1420 | my ($value) = @_; | |||||
| 1421 | ||||||
| 1422 | return '' unless defined($value); | |||||
| 1423 | return "$value" if(!ref($value) || Scalar::Util::blessed($value)); | |||||
| 1424 | return _to_json($value); | |||||
| 1425 | 37 37 37 | 5170 24 97 | } | |||
| 1426 | ||||||
| 1427 | # --------------------------------------------------------------------------- | |||||
| 1428 | # _fields_text -- render structured fields as logfmt-style key=value pairs | |||||
| 1429 | # | |||||
| 1430 | # Purpose: Text formats, syslog, email and object backends have no field | |||||
| 1431 | # support, so the fields are appended to the message as text. | |||||
| 1432 | # Entry: $fields -- a hashref of field names to values. | |||||
| 1433 | # Exit: Returns 'key=value key2="value 2"', with keys in sorted order. | |||||
| 1434 | # Notes: A pure function (no $self), called as _fields_text($fields). | |||||
| 1435 | # Characters outside [\w.-] in a key become '_'. A value that | |||||
| 1436 | # is empty or contains white space, '"', '=' or '\' is quoted, | |||||
| 1437 | # with '"' and '\' escaped and control characters written as | |||||
| 1438 | # \n, \r, \t or \xNN, so a field can never contain a line break | |||||
| 1439 | # and forge a log entry. | |||||
| 1440 | # --------------------------------------------------------------------------- | |||||
| 1441 | sub _fields_text :Private { | |||||
| 1442 | my ($fields) = @_; | |||||
| 1443 | ||||||
| 1444 | my %escapes = ("\n" => '\n', "\r" => '\r', "\t" => '\t'); | |||||
| 1445 | my @pairs; | |||||
| 1446 | for my $name (sort keys %{$fields}) { | |||||
| 1447 | (my $key = $name) =~ s/[^\w.\-]/_/g; | |||||
| 1448 | my $value = _field_string($fields->{$name}); | |||||
| 1449 | if(($value eq '') || ($value =~ /[\s"=\\\x00-\x1F\x7F]/)) { | |||||
| 1450 | $value =~ s/(["\\])/\\$1/g; | |||||
| 1451 | $value =~ s/([\x00-\x1F\x7F])/$escapes{$1} \/\/ sprintf('\\x%02x', ord($1))/ge; | |||||
| 1452 | $value = qq{"$value"}; | |||||
| 1453 | } | |||||
| 1454 | push @pairs, "$key=$value"; | |||||
| 1455 | } | |||||
| 1456 | return join(' ', @pairs); | |||||
| 1457 | 37 37 37 | 8693 24 139 | } | |||
| 1458 | ||||||
| 1459 | # --------------------------------------------------------------------------- | |||||
| 1460 | # _check_timestamp_args -- validate the timestamp options given to new() | |||||
| 1461 | # | |||||
| 1462 | # Purpose: Croak in new() (and when cloning) on a bad timestamp_format | |||||
| 1463 | # or timestamp_precision, rather than log a broken timestamp. | |||||
| 1464 | # Entry: $class -- the class name, for the error message. | |||||
| 1465 | # $args -- hashref of constructor arguments. | |||||
| 1466 | # Exit: Returns nothing; croaks on an invalid value. | |||||
| 1467 | # Notes: A pure function (no $self), called as | |||||
| 1468 | # _check_timestamp_args($class, \%args). | |||||
| 1469 | # --------------------------------------------------------------------------- | |||||
| 1470 | sub _check_timestamp_args :Private { | |||||
| 1471 | my ($class, $args) = @_; | |||||
| 1472 | ||||||
| 1473 | if(exists($args->{'timestamp_format'})) { | |||||
| 1474 | my $format = $args->{'timestamp_format'}; | |||||
| 1475 | if(!defined($format) || ref($format) || ($format eq '')) { | |||||
| 1476 | Carp::croak("$class: timestamp_format must be a non-empty string"); | |||||
| 1477 | } | |||||
| 1478 | } | |||||
| 1479 | if(defined(my $precision = $args->{'timestamp_precision'})) { | |||||
| 1480 | if(($precision !~ /^\d+$/) || ($precision > $MAX_TIMESTAMP_PRECISION)) { | |||||
| 1481 | Carp::croak("$class: timestamp_precision must be an integer from 0 to $MAX_TIMESTAMP_PRECISION, not '$precision'"); | |||||
| 1482 | } | |||||
| 1483 | } | |||||
| 1484 | return; | |||||
| 1485 | 37 37 37 | 6597 21 125 | } | |||
| 1486 | ||||||
| 1487 | # --------------------------------------------------------------------------- | |||||
| 1488 | # _utc_offset -- the local time zone's offset from UTC at a given time | |||||
| 1489 | # | |||||
| 1490 | # Purpose: Portable %z/%:z, and local period boundaries for rotation. | |||||
| 1491 | # Entry: $secs -- epoch seconds. | |||||
| 1492 | # $utc -- true to return 0 (timestamps are in UTC). | |||||
| 1493 | # Exit: Returns the offset in seconds (negative west of Greenwich). | |||||
| 1494 | # Notes: A pure function (no $self), called as _utc_offset($secs, $utc). | |||||
| 1495 | # The offset is what the local broken-down time would be as | |||||
| 1496 | # UTC, less the real time. The year is passed in full so that | |||||
| 1497 | # Time::Local doesn't guess a century. | |||||
| 1498 | # --------------------------------------------------------------------------- | |||||
| 1499 | sub _utc_offset :Private { | |||||
| 1500 | my ($secs, $utc) = @_; | |||||
| 1501 | ||||||
| 1502 | return 0 if($utc); | |||||
| 1503 | my @tm = localtime($secs); | |||||
| 1504 | return Time::Local::timegm(@tm[0..4], $tm[5] + 1900) - $secs; | |||||
| 1505 | 37 37 37 | 5625 34 98 | } | |||
| 1506 | ||||||
| 1507 | # --------------------------------------------------------------------------- | |||||
| 1508 | # _check_rotate_args -- validate and normalise the file-rotation options | |||||
| 1509 | # | |||||
| 1510 | # Purpose: Croak in new() (and when cloning) on a bad rotate_size, | |||||
| 1511 | # rotate_interval or rotate_keep, rather than fail at log time. | |||||
| 1512 | # Entry: $class -- the class name, for the error message. | |||||
| 1513 | # $args -- hashref of constructor arguments; changed in place. | |||||
| 1514 | # Exit: Returns nothing. rotate_size becomes a number of bytes and | |||||
| 1515 | # rotate_interval is lower-cased. Croaks on an invalid value. | |||||
| 1516 | # Notes: A pure function (no $self), called as | |||||
| 1517 | # _check_rotate_args($class, \%args). | |||||
| 1518 | # --------------------------------------------------------------------------- | |||||
| 1519 | sub _check_rotate_args :Private { | |||||
| 1520 | my ($class, $args) = @_; | |||||
| 1521 | ||||||
| 1522 | if(defined(my $size = $args->{'rotate_size'})) { | |||||
| 1523 | if($size !~ /^\s*(\d+)\s*([kmg]?)b?\s*$/i || ($1 == 0)) { | |||||
| 1524 | Carp::croak("$class: rotate_size must be a positive number of bytes, optionally with K, M or G, not '$size'"); | |||||
| 1525 | } | |||||
| 1526 | $args->{'rotate_size'} = $1 * $SIZE_UNITS{lc($2)}; | |||||
| 1527 | } | |||||
| 1528 | if(defined(my $interval = $args->{'rotate_interval'})) { | |||||
| 1529 | if(!$ROTATE_PERIOD{lc($interval)}) { | |||||
| 1530 | Carp::croak("$class: rotate_interval must be hourly, daily, weekly or monthly, not '$interval'"); | |||||
| 1531 | } | |||||
| 1532 | $args->{'rotate_interval'} = lc($interval); | |||||
| 1533 | } | |||||
| 1534 | if(defined(my $keep = $args->{'rotate_keep'})) { | |||||
| 1535 | if($keep !~ /^\d+$/) { | |||||
| 1536 | Carp::croak("$class: rotate_keep must be a non-negative integer, not '$keep'"); | |||||
| 1537 | } | |||||
| 1538 | } | |||||
| 1539 | if(defined(my $interval = $args->{'reopen_interval'})) { | |||||
| 1540 | if($interval !~ /^(?:\d+|-1)\z/) { | |||||
| 1541 | Carp::croak("$class: reopen_interval must be a number of seconds, 0 or -1, not '$interval'"); | |||||
| 1542 | } | |||||
| 1543 | } | |||||
| 1544 | return; | |||||
| 1545 | 37 37 37 | 8981 13 118 | } | |||
| 1546 | ||||||
| 1547 | # --------------------------------------------------------------------------- | |||||
| 1548 | # _check_redact_args -- validate the redact option and compile it | |||||
| 1549 | # | |||||
| 1550 | # Purpose: Croak in new() (and when cloning) on a bad redact pattern, | |||||
| 1551 | # rather than leave a secret in the log. | |||||
| 1552 | # Entry: $class -- the class name, for the error message. | |||||
| 1553 | # $args -- hashref of constructor arguments; changed in place. | |||||
| 1554 | # Exit: Returns nothing. redact, a regex, a string or an arrayref of | |||||
| 1555 | # them, becomes one regex that matches any of them, or undef | |||||
| 1556 | # when there are none. Croaks on a pattern that isn't a regex | |||||
| 1557 | # or non-empty string, doesn't compile, or matches ''. | |||||
| 1558 | # Notes: A pure function (no $self), called as | |||||
| 1559 | # _check_redact_args($class, \%args). Strings are allowed | |||||
| 1560 | # because a config file can't hold a qr//. One combined regex | |||||
| 1561 | # means one pass, so a replacement is never matched again. | |||||
| 1562 | # | |||||
| 1563 | # Pseudocode: | |||||
| 1564 | # FUNCTION _check_redact_args(class, args) | |||||
| 1565 | # RETURN unless args has a redact key | |||||
| 1566 | # patterns = the defined elements of redact (an arrayref) or redact itself | |||||
| 1567 | # FOR each pattern that isn't already a regex: | |||||
| 1568 | # CROAK if it is a reference or '' | |||||
| 1569 | # compile it (in eval); CROAK with the error, less its location, if | |||||
| 1570 | # it doesn't compile | |||||
| 1571 | # IF no patterns: set redact to undef; RETURN | |||||
| 1572 | # CROAK if any pattern matches '' | |||||
| 1573 | # set redact to qr/(?:p1)|(?:p2)|.../ | |||||
| 1574 | # END FUNCTION | |||||
| 1575 | # --------------------------------------------------------------------------- | |||||
| 1576 | sub _check_redact_args :Private { | |||||
| 1577 | my ($class, $args) = @_; | |||||
| 1578 | ||||||
| 1579 | return if(!exists($args->{'redact'})); | |||||
| 1580 | my $redact = $args->{'redact'}; | |||||
| 1581 | my @patterns = grep { defined } ((ref($redact) eq 'ARRAY') ? @{$redact} : ($redact)); | |||||
| 1582 | for my $pattern (@patterns) { | |||||
| 1583 | next if(re::is_regexp($pattern)); | |||||
| 1584 | if(ref($pattern) || ($pattern eq '')) { | |||||
| 1585 | Carp::croak("$class: redact patterns must be regular expressions or non-empty strings"); | |||||
| 1586 | } | |||||
| 1587 | my $re = eval { qr/$pattern/ }; | |||||
| 1588 | if(!$re) { | |||||
| 1589 | (my $error = $@) =~ s/ at \S+ line \d+\.?\n\z//; | |||||
| 1590 | Carp::croak("$class: invalid redact pattern '$pattern': $error"); | |||||
| 1591 | } | |||||
| 1592 | $pattern = $re; | |||||
| 1593 | } | |||||
| 1594 | if(!@patterns) { | |||||
| 1595 | $args->{'redact'} = undef; | |||||
| 1596 | return; | |||||
| 1597 | } | |||||
| 1598 | for my $pattern (@patterns) { | |||||
| 1599 | # It would put a marker between every character | |||||
| 1600 | if('' =~ $pattern) { | |||||
| 1601 | Carp::croak("$class: redact pattern $pattern matches the empty string"); | |||||
| 1602 | } | |||||
| 1603 | } | |||||
| 1604 | my $any = join('|', map { "(?:$_)" } @patterns); | |||||
| 1605 | $args->{'redact'} = qr/$any/; | |||||
| 1606 | return; | |||||
| 1607 | 37 37 37 | 8823 20 203 | } | |||
| 1608 | ||||||
| 1609 | # --------------------------------------------------------------------------- | |||||
| 1610 | # _redact -- replace whatever matches the redact regex with [REDACTED] | |||||
| 1611 | # | |||||
| 1612 | # Purpose: Remove secrets from a message or a structured-field value | |||||
| 1613 | # before it reaches the history or any backend. | |||||
| 1614 | # Entry: $re -- the regex built by _check_redact_args. | |||||
| 1615 | # $value -- a string, or a field value of any kind. | |||||
| 1616 | # $seen -- (recursion only) the references being walked. | |||||
| 1617 | # Exit: Returns the redacted copy; the value itself is unchanged. | |||||
| 1618 | # Plain hashes and arrays are copied with their contents | |||||
| 1619 | # redacted; a blessed object whose stringification matches | |||||
| 1620 | # becomes the redacted string; any other value is returned | |||||
| 1621 | # as it is. A reference that contains itself is replaced by | |||||
| 1622 | # the marker where it recurs. | |||||
| 1623 | # Notes: A pure function (no $self), called as _redact($re, $value). | |||||
| 1624 | # | |||||
| 1625 | # Pseudocode: | |||||
| 1626 | # FUNCTION _redact(re, value, seen) | |||||
| 1627 | # RETURN value if undef | |||||
| 1628 | # IF blessed: RETURN _redact(re, "value") if "value" matches re, else value | |||||
| 1629 | # IF a reference: | |||||
| 1630 | # RETURN value unless a plain HASH or ARRAY | |||||
| 1631 | # RETURN the marker if value is in seen (it contains itself) | |||||
| 1632 | # add value to seen while walking it (local, so siblings may share it) | |||||
| 1633 | # RETURN a copy with each element/value passed through _redact | |||||
| 1634 | # replace every match of re in (a copy of) value with the marker | |||||
| 1635 | # RETURN it | |||||
| 1636 | # END FUNCTION | |||||
| 1637 | # --------------------------------------------------------------------------- | |||||
| 1638 | sub _redact :Private { | |||||
| 1639 | my ($re, $value, $seen) = @_; | |||||
| 1640 | ||||||
| 1641 | return $value if(!defined($value)); | |||||
| 1642 | if(Scalar::Util::blessed($value)) { | |||||
| 1643 | my $string = "$value"; | |||||
| 1644 | return $value unless $string =~ $re; | |||||
| 1645 | $string =~ s/$re/$REDACTED_MARKER/g; | |||||
| 1646 | return $string; | |||||
| 1647 | } | |||||
| 1648 | if(my $type = ref($value)) { | |||||
| 1649 | return $value if(($type ne 'HASH') && ($type ne 'ARRAY')); | |||||
| 1650 | $seen ||= {}; | |||||
| 1651 | return $REDACTED_MARKER if($seen->{$value}); | |||||
| 1652 | local $seen->{$value} = 1; | |||||
| 1653 | return ($type eq 'HASH') | |||||
| 1654 | ? { map { $_ => _redact($re, $value->{$_}, $seen) } keys %{$value} } | |||||
| 1655 | : [ map { _redact($re, $_, $seen) } @{$value} ]; | |||||
| 1656 | } | |||||
| 1657 | $value =~ s/$re/$REDACTED_MARKER/g; | |||||
| 1658 | return $value; | |||||
| 1659 | 37 37 37 | 7124 46 148 | } | |||
| 1660 | ||||||
| 1661 | # --------------------------------------------------------------------------- | |||||
| 1662 | # _rotate -- rotate a log file if it is too big or from an earlier period | |||||
| 1663 | # | |||||
| 1664 | # Purpose: Size- and time-based rotation for the file backends. | |||||
| 1665 | # Entry: $self -- the logger object (rotate_size, rotate_interval, | |||||
| 1666 | # rotate_keep and utc). | |||||
| 1667 | # $path -- the validated log-file path, about to be appended to. | |||||
| 1668 | # Exit: Returns nothing. Croaks if a rename fails (autodie); | |||||
| 1669 | # _write_line calls this in an eval of its own, so the line is | |||||
| 1670 | # still written. | |||||
| 1671 | # Side effects: Renames FILE to FILE.1, FILE.1 to FILE.2 and so on, deleting | |||||
| 1672 | # FILE.<rotate_keep>; with rotate_keep 0, deletes FILE. | |||||
| 1673 | # Notes: Called before each write, so it costs one stat() per line. | |||||
| 1674 | # Time-based rotation compares the file's last-modified time | |||||
| 1675 | # with now, so a file not written to for a while rotates on the | |||||
| 1676 | # next write. Not safe for several processes rotating the same | |||||
| 1677 | # file; use logrotate for that. | |||||
| 1678 | # | |||||
| 1679 | # Pseudocode: | |||||
| 1680 | # FUNCTION _rotate(self, path) | |||||
| 1681 | # RETURN unless stat(path) succeeds (no file yet) | |||||
| 1682 | # due = rotate_size AND file size >= rotate_size | |||||
| 1683 | # IF NOT due AND rotate_interval: | |||||
| 1684 | # period = ROTATE_PERIOD{rotate_interval} | |||||
| 1685 | # due = period(mtime) < period(now), each with its own UTC offset | |||||
| 1686 | # RETURN unless due | |||||
| 1687 | # close the logger's handle on path | |||||
| 1688 | # keep = rotate_keep // 5 | |||||
| 1689 | # IF keep == 0: unlink path; RETURN | |||||
| 1690 | # unlink path.keep if it exists | |||||
| 1691 | # FOR i = keep-1 down to 1: rename path.i to path.(i+1) if it exists | |||||
| 1692 | # rename path to path.1 | |||||
| 1693 | # END FUNCTION | |||||
| 1694 | # --------------------------------------------------------------------------- | |||||
| 1695 | sub _rotate :Private { | |||||
| 1696 | my ($self, $path) = @_; | |||||
| 1697 | ||||||
| 1698 | my @st = stat($path) or return; | |||||
| 1699 | my ($size, $mtime) = @st[7, 9]; | |||||
| 1700 | ||||||
| 1701 | my $due = $self->{'rotate_size'} && ($size >= $self->{'rotate_size'}); | |||||
| 1702 | if(!$due && (my $interval = $self->{'rotate_interval'})) { | |||||
| 1703 | my $utc = $self->{'utc'}; | |||||
| 1704 | my $period = $ROTATE_PERIOD{$interval}; | |||||
| 1705 | my $now = time(); | |||||
| 1706 | $due = $period->($mtime, _utc_offset($mtime, $utc), $utc) < $period->($now, _utc_offset($now, $utc), $utc); | |||||
| 1707 | } | |||||
| 1708 | return unless($due); | |||||
| 1709 | ||||||
| 1710 | # Close the file first: Windows can't rename or delete an open file | |||||
| 1711 | $self->_close_files($path); | |||||
| 1712 | ||||||
| 1713 | my $keep = $self->{'rotate_keep'} // $DEFAULT_ROTATE_KEEP; | |||||
| 1714 | if($keep == 0) { | |||||
| 1715 | unlink($path); | |||||
| 1716 | return; | |||||
| 1717 | } | |||||
| 1718 | # Unlink before each rename: Windows can't rename onto an existing file | |||||
| 1719 | unlink("$path.$keep") if(-e "$path.$keep"); | |||||
| 1720 | for my $i (reverse(1 .. $keep - 1)) { | |||||
| 1721 | rename("$path.$i", "$path." . ($i + 1)) if(-e "$path.$i"); | |||||
| 1722 | } | |||||
| 1723 | rename($path, "$path.1"); | |||||
| 1724 | return; | |||||
| 1725 | 37 37 37 | 7690 19 136 | } | |||
| 1726 | ||||||
| 1727 | # --------------------------------------------------------------------------- | |||||
| 1728 | # _timestamp -- the time of a log call, formatted for log lines | |||||
| 1729 | # | |||||
| 1730 | # Purpose: Single source of %timestamp% and the JSON 'timestamp' value, | |||||
| 1731 | # honouring timestamp_format, utc and timestamp_precision. | |||||
| 1732 | # Entry: $self -- the logger object. | |||||
| 1733 | # $now -- optional epoch seconds, possibly fractional | |||||
| 1734 | # (default: Time::HiRes::time()). | |||||
| 1735 | # Exit: Returns the formatted timestamp string. | |||||
| 1736 | # Notes: Extends strftime with %N (fractional seconds; %3N, %6N etc. | |||||
| 1737 | # give that many digits, truncated, not rounded), %z (+hhmm) | |||||
| 1738 | # and %:z (+hh:mm), computed here because Windows' strftime | |||||
| 1739 | # gives a zone name for %z; and in UTC, %Z is 'UTC'. A '%%' | |||||
| 1740 | # is passed through, so '%%N' is a literal '%N'. | |||||
| 1741 | # | |||||
| 1742 | # Pseudocode: | |||||
| 1743 | # FUNCTION _timestamp(self, now) | |||||
| 1744 | # now = now // Time::HiRes::time(); secs = int(now) | |||||
| 1745 | # tm = utc ? gmtime(secs) : localtime(secs) | |||||
| 1746 | # format = timestamp_format, or the default | |||||
| 1747 | # 'iso8601'/'rfc3339' (any case) -> '%Y-%m-%dT%H:%M:%S' + ('Z' if utc, else '%:z') | |||||
| 1748 | # IF timestamp_precision > 0: follow each %S with '.%<precision>N' | |||||
| 1749 | # Replace, in one pass: | |||||
| 1750 | # %% -> %% (left for strftime) | |||||
| 1751 | # %nN -> first n (default 9) digits of the fraction of now | |||||
| 1752 | # %z -> +hhmm, %:z -> +hh:mm (offset = timegm(tm) - secs; 0 in UTC) | |||||
| 1753 | # %Z -> 'UTC' if utc (else left for strftime) | |||||
| 1754 | # RETURN strftime(format, tm) | |||||
| 1755 | # END FUNCTION | |||||
| 1756 | # --------------------------------------------------------------------------- | |||||
| 1757 | sub _timestamp :Private { | |||||
| 1758 | my ($self, $now) = @_; | |||||
| 1759 | ||||||
| 1760 | $now //= Time::HiRes::time(); | |||||
| 1761 | my $secs = int($now); | |||||
| 1762 | my $utc = $self->{'utc'}; | |||||
| 1763 | my @tm = $utc ? gmtime($secs) : localtime($secs); | |||||
| 1764 | ||||||
| 1765 | my $format = $self->{'timestamp_format'} // $DEFAULT_TIMESTAMP_FORMAT; | |||||
| 1766 | if($format =~ /^(?:iso8601|rfc3339)$/i) { | |||||
| 1767 | $format = $RFC3339_TIMESTAMP_FORMAT . ($utc ? 'Z' : '%:z'); | |||||
| 1768 | } | |||||
| 1769 | if(my $precision = $self->{'timestamp_precision'}) { | |||||
| 1770 | $format =~ s/%(%|S)/($1 eq 'S') ? "%S.%${precision}N" : '%%'/ge; | |||||
| 1771 | } | |||||
| 1772 | ||||||
| 1773 | my $offset = sub { | |||||
| 1774 | my ($colon) = @_; | |||||
| 1775 | my $diff = _utc_offset($secs, $utc); | |||||
| 1776 | my $sign = ($diff < 0) ? '-' : '+'; | |||||
| 1777 | $diff = abs($diff); | |||||
| 1778 | return sprintf('%s%02d%s%02d', $sign, int($diff / 3600), $colon, int(($diff % 3600) / 60)); | |||||
| 1779 | }; | |||||
| 1780 | ||||||
| 1781 | $format =~ s/%(%|([1-9]?)N|:z|z|Z)/ | |||||
| 1782 | ($1 eq '%') ? '%%' | |||||
| 1783 | : defined($2) ? substr(sprintf('%09d', int(($now - $secs) * 1e9)), 0, $2 || $MAX_TIMESTAMP_PRECISION) | |||||
| 1784 | : ($1 eq ':z') ? $offset->(':') | |||||
| 1785 | : ($1 eq 'z') ? $offset->('') | |||||
| 1786 | : $utc ? 'UTC' : '%Z'/gex; | |||||
| 1787 | ||||||
| 1788 | return POSIX::strftime($format, @tm); | |||||
| 1789 | 37 37 37 | 9520 18 133 | } | |||
| 1790 | ||||||
| 1791 | # --------------------------------------------------------------------------- | |||||
| 1792 | # _write_line -- append one formatted line to a file path or filehandle | |||||
| 1793 | # | |||||
| 1794 | # Purpose: Single output path for the file, fd and scalar-path backends. | |||||
| 1795 | # Entry: $self -- the logger object. | |||||
| 1796 | # $target -- a validated file path, or an open filehandle. | |||||
| 1797 | # $line -- the formatted line, without trailing newline. | |||||
| 1798 | # Exit: Returns nothing. | |||||
| 1799 | # Side effects: Appends to the file or prints to the handle. A file path | |||||
| 1800 | # is rotated first if rotate_size or rotate_interval says so, | |||||
| 1801 | # and is kept open for the next line (see _file_handle), unless | |||||
| 1802 | # reopen_interval is 0. | |||||
| 1803 | # Notes: Character strings are encoded to UTF-8, avoiding "Wide | |||||
| 1804 | # character" warnings, unless the handle already has a | |||||
| 1805 | # :utf8 or :encoding layer. File I/O failures are silent by | |||||
| 1806 | # design: an I/O error must never crash the application. | |||||
| 1807 | # --------------------------------------------------------------------------- | |||||
| 1808 | sub _write_line :Private { | |||||
| 1809 | my ($self, $target, $line) = @_; | |||||
| 1810 | ||||||
| 1811 | if(ref($target)) { | |||||
| 1812 | if(utf8::is_utf8($line) | |||||
| 1813 | && !grep { /^(?:utf8|encoding)/ } PerlIO::get_layers($target)) { | |||||
| 1814 | utf8::encode($line); | |||||
| 1815 | } | |||||
| 1816 | print $target "$line\n"; | |||||
| 1817 | return; | |||||
| 1818 | } | |||||
| 1819 | ||||||
| 1820 | utf8::encode($line) if(utf8::is_utf8($line)); | |||||
| 1821 | ||||||
| 1822 | # Rotate in its own eval: if a rename fails (autodie), still write the line | |||||
| 1823 | if($self->{'rotate_size'} || $self->{'rotate_interval'}) { | |||||
| 1824 | eval { $self->_rotate($target) }; | |||||
| 1825 | } | |||||
| 1826 | # A failed write closes the file, so that the next one opens it again | |||||
| 1827 | eval { | |||||
| 1828 | my $fout = $self->_file_handle($target); | |||||
| 1829 | print $fout "$line\n" or die "$target: $!"; | |||||
| 1830 | 1; | |||||
| 1831 | } or $self->_close_files($target); | |||||
| 1832 | ||||||
| 1833 | # reopen_interval 0: never hold the file open, as before 0.40 | |||||
| 1834 | if(($self->{'reopen_interval'} // $DEFAULT_REOPEN_INTERVAL) == $REOPEN_EVERY_WRITE) { | |||||
| 1835 | $self->_close_files($target); | |||||
| 1836 | } | |||||
| 1837 | return; | |||||
| 1838 | 37 37 37 | 7844 18 120 | } | |||
| 1839 | ||||||
| 1840 | # --------------------------------------------------------------------------- | |||||
| 1841 | # _file_handle -- the logger's open handle on a log file | |||||
| 1842 | # | |||||
| 1843 | # Purpose: Keep log files open between messages, rather than opening | |||||
| 1844 | # and closing them for every line. | |||||
| 1845 | # Entry: $self -- the logger object (reopen_interval, and the open | |||||
| 1846 | # handles in $self->{_handles}). | |||||
| 1847 | # $path -- a validated log-file path. | |||||
| 1848 | # Exit: Returns a handle open for appending, with autoflush on. | |||||
| 1849 | # Croaks (autodie) if the file can't be opened. | |||||
| 1850 | # Side effects: Opens the file if the logger hasn't, or opens it again if | |||||
| 1851 | # the path is now a different file (renamed or deleted, e.g. | |||||
| 1852 | # by logrotate), the process has had a SIGHUP, or | |||||
| 1853 | # reopen_interval seconds have passed since it was opened | |||||
| 1854 | # (never with -1). Installs the SIGHUP handler | |||||
| 1855 | # (_catch_sighup) when it opens a file, unless reopen_interval | |||||
| 1856 | # is 0, when _write_line closes the file again at once. | |||||
| 1857 | # Notes: Costs one stat() per line. The device and inode are taken | |||||
| 1858 | # from the path, not the handle, so that the two are compared | |||||
| 1859 | # alike (Windows' fstat can differ). | |||||
| 1860 | # | |||||
| 1861 | # Pseudocode: | |||||
| 1862 | # FUNCTION _file_handle(self, path) | |||||
| 1863 | # IF the logger has a handle on path: | |||||
| 1864 | # RETURN it IF path still names the same device and inode AND | |||||
| 1865 | # there has been no SIGHUP since it was opened AND | |||||
| 1866 | # (reopen_interval is -1 OR it was opened less than that long ago) | |||||
| 1867 | # close it | |||||
| 1868 | # install the SIGHUP handler, unless done already, on Windows, or | |||||
| 1869 | # reopen_interval is 0 | |||||
| 1870 | # open path for appending, autoflush on | |||||
| 1871 | # remember the handle, path's device and inode, the SIGHUP count and | |||||
| 1872 | # the time | |||||
| 1873 | # RETURN the handle | |||||
| 1874 | # END FUNCTION | |||||
| 1875 | # --------------------------------------------------------------------------- | |||||
| 1876 | sub _file_handle :Private { | |||||
| 1877 | my ($self, $path) = @_; | |||||
| 1878 | ||||||
| 1879 | if(my $open = $self->{_handles}{$path}) { | |||||
| 1880 | my @st = stat($path); | |||||
| 1881 | my $interval = $self->{'reopen_interval'} // $DEFAULT_REOPEN_INTERVAL; | |||||
| 1882 | if(@st && ($st[0] == $open->{dev}) && ($st[1] == $open->{ino}) | |||||
| 1883 | && ($open->{sighup} == $sighup_count) | |||||
| 1884 | && (($interval == $REOPEN_ON_SIGHUP) || ((time() - $open->{opened}) < $interval))) { | |||||
| 1885 | return $open->{fh}; | |||||
| 1886 | } | |||||
| 1887 | $self->_close_files($path); | |||||
| 1888 | } | |||||
| 1889 | ||||||
| 1890 | $self->_catch_sighup() unless(($self->{'reopen_interval'} // $DEFAULT_REOPEN_INTERVAL) == $REOPEN_EVERY_WRITE); | |||||
| 1891 | open(my $fh, '>>', $path); | |||||
| 1892 | $fh->autoflush(1); | |||||
| 1893 | my @st = stat($path); | |||||
| 1894 | $self->{_handles}{$path} = { | |||||
| 1895 | fh => $fh, dev => $st[0], ino => $st[1], sighup => $sighup_count, opened => time(), | |||||
| 1896 | }; | |||||
| 1897 | return $fh; | |||||
| 1898 | 37 37 37 | 7649 16 113 | } | |||
| 1899 | ||||||
| 1900 | # --------------------------------------------------------------------------- | |||||
| 1901 | # _catch_sighup -- reopen the log files when the process gets a SIGHUP | |||||
| 1902 | # | |||||
| 1903 | # Purpose: logrotate's postrotate script, and similar tools, send | |||||
| 1904 | # SIGHUP to tell a program to reopen its log files. | |||||
| 1905 | # Entry: $self -- the logger opening a file. | |||||
| 1906 | # Exit: Returns nothing. | |||||
| 1907 | # Side effects: Except on Windows, counts the logger as a user of the | |||||
| 1908 | # handler (_sighup), and if no logger has installed it, saves | |||||
| 1909 | # $SIG{HUP} and sets it to a handler that counts the signal | |||||
| 1910 | # (see $sighup_count) and then calls the saved handler, if it | |||||
| 1911 | # is a code reference or a sub name. So SIGHUP doesn't end | |||||
| 1912 | # the process by default while a logger uses the handler; | |||||
| 1913 | # _release_sighup puts the saved one back. | |||||
| 1914 | # Notes: Called when a file is opened, so a program that never logs | |||||
| 1915 | # to a file keeps its SIGHUP behaviour. A handler the program | |||||
| 1916 | # sets afterwards replaces this one; reopen_interval still | |||||
| 1917 | # reopens the files. | |||||
| 1918 | # --------------------------------------------------------------------------- | |||||
| 1919 | sub _catch_sighup :Private { | |||||
| 1920 | my $self = $_[0]; | |||||
| 1921 | ||||||
| 1922 | return if($self->{_sighup} || ($^O eq 'MSWin32')); | |||||
| 1923 | $self->{_sighup} = 1; | |||||
| 1924 | $sighup_users++; | |||||
| 1925 | return if($sighup_handler); | |||||
| 1926 | ||||||
| 1927 | $sighup_previous = $SIG{HUP}; | |||||
| 1928 | my $chain = $sighup_previous; | |||||
| 1929 | if(defined($chain) && !ref($chain)) { | |||||
| 1930 | $chain = undef if(($chain eq '') || ($chain eq 'IGNORE') || ($chain eq 'DEFAULT')); | |||||
| 1931 | $chain = "main::$chain" if(defined($chain) && ($chain !~ /::/)); | |||||
| 1932 | } | |||||
| 1933 | $sighup_handler = sub { | |||||
| 1934 | $sighup_count++; | |||||
| 1935 | if(defined($chain)) { | |||||
| 1936 | 37 37 37 | 6689 19 922 | no strict 'refs'; | |||
| 1937 | $chain->(@_); | |||||
| 1938 | } | |||||
| 1939 | }; | |||||
| 1940 | $SIG{HUP} = $sighup_handler; | |||||
| 1941 | return; | |||||
| 1942 | 37 37 37 | 29 26 104 | } | |||
| 1943 | ||||||
| 1944 | # --------------------------------------------------------------------------- | |||||
| 1945 | # _release_sighup -- stop using the SIGHUP handler | |||||
| 1946 | # | |||||
| 1947 | # Purpose: Give the program its own SIGHUP handler back when no logger | |||||
| 1948 | # needs this module's. | |||||
| 1949 | # Entry: $self -- a logger being destroyed. | |||||
| 1950 | # Exit: Returns nothing. | |||||
| 1951 | # Side effects: If the logger used the handler and was the last to, puts | |||||
| 1952 | # back the $SIG{HUP} that _catch_sighup replaced, unless the | |||||
| 1953 | # program has set a handler of its own since; the next logger | |||||
| 1954 | # to open a file installs the handler again. | |||||
| 1955 | # --------------------------------------------------------------------------- | |||||
| 1956 | sub _release_sighup :Private { | |||||
| 1957 | my $self = $_[0]; | |||||
| 1958 | ||||||
| 1959 | return unless(delete $self->{_sighup}); | |||||
| 1960 | return if(--$sighup_users > 0); | |||||
| 1961 | ||||||
| 1962 | my $current = $SIG{HUP}; | |||||
| 1963 | if($sighup_handler && ref($current) && ($current == $sighup_handler)) { | |||||
| 1964 | $SIG{HUP} = (defined($sighup_previous) && length($sighup_previous)) ? $sighup_previous : 'DEFAULT'; | |||||
| 1965 | } | |||||
| 1966 | $sighup_handler = $sighup_previous = undef; | |||||
| 1967 | return; | |||||
| 1968 | 37 37 37 | 5957 25 110 | } | |||
| 1969 | ||||||
| 1970 | # --------------------------------------------------------------------------- | |||||
| 1971 | # _close_files -- close log files that the logger holds open | |||||
| 1972 | # | |||||
| 1973 | # Purpose: Used by reopen(), before a rotation, and after a failed write. | |||||
| 1974 | # Entry: $self -- the logger object. | |||||
| 1975 | # @paths -- the files to close; none means all of them. | |||||
| 1976 | # Exit: Returns nothing. | |||||
| 1977 | # Side effects: Closes the handles and forgets them, so the next write opens | |||||
| 1978 | # the file again. A failing close is ignored. | |||||
| 1979 | # --------------------------------------------------------------------------- | |||||
| 1980 | sub _close_files :Private { | |||||
| 1981 | my ($self, @paths) = @_; | |||||
| 1982 | ||||||
| 1983 | my $handles = $self->{_handles} or return; | |||||
| 1984 | for my $path (@paths ? @paths : keys(%{$handles})) { | |||||
| 1985 | my $open = delete $handles->{$path} or next; | |||||
| 1986 | eval { close($open->{fh}) }; | |||||
| 1987 | } | |||||
| 1988 | return; | |||||
| 1989 | 37 37 37 | 5690 20 93 | } | |||
| 1990 | ||||||
| 1991 | # --------------------------------------------------------------------------- | |||||
| 1992 | # _send_email -- send one email: any held digest, then the new lines | |||||
| 1993 | # | |||||
| 1994 | # Purpose: The sendmail backend's delivery, shared by _log and flush(). | |||||
| 1995 | # Entry: $self -- the logger object (the digest and throttle state). | |||||
| 1996 | # $sm -- the sendmail hash (to, from, subject, host, port, | |||||
| 1997 | # digest, async). | |||||
| 1998 | # @lines -- the bodies of the new messages (none from flush). | |||||
| 1999 | # Exit: Returns 1 if the email was sent or there was nothing to | |||||
| 2000 | # send, 0 if delivery failed. | |||||
| 2001 | # Side effects: Croaks on an invalid host or port, before the eval so that | |||||
| 2002 | # the misconfiguration isn't hidden. On success, clears the | |||||
| 2003 | # digest and starts the min_interval throttle. On failure, | |||||
| 2004 | # carps, and with digest holds @lines for the next email (the | |||||
| 2005 | # digest already held stays held). | |||||
| 2006 | # Notes: The body is the held lines, a "... and N more" line if some | |||||
| 2007 | # were dropped, then @lines, one per line; a single message | |||||
| 2008 | # with nothing held is sent exactly as it is. | |||||
| 2009 | # With async (not on Windows, nor while perl is exiting), a | |||||
| 2010 | # forked child sends the email and this returns 1 at once, as | |||||
| 2011 | # if it had been sent: the child carps a failure itself, and | |||||
| 2012 | # the lines are lost. If fork fails, the email is sent here. | |||||
| 2013 | # | |||||
| 2014 | # Pseudocode: | |||||
| 2015 | # FUNCTION _send_email(self, sm, lines...) | |||||
| 2016 | # CROAK if host contains unsafe characters, or port isn't 1-65535 | |||||
| 2017 | # body = held digest, "... and N more" if N were dropped, lines | |||||
| 2018 | # RETURN 1 if body is empty | |||||
| 2019 | # deliver = load Email::* modules; build email with sanitised headers | |||||
| 2020 | # and body joined with newlines; send via SMTP transport | |||||
| 2021 | # IF sm->{async} AND not Windows AND perl isn't exiting: | |||||
| 2022 | # reap finished children | |||||
| 2023 | # fork | |||||
| 2024 | # IN THE CHILD: (eval) deliver; CARP on failure; _exit | |||||
| 2025 | # IN THE PARENT, if the fork worked: remember the child; clear the | |||||
| 2026 | # digest; record the time for the throttle; RETURN 1 | |||||
| 2027 | # (eval) deliver | |||||
| 2028 | # IF it failed: | |||||
| 2029 | # CARP; IF sm->{digest}: hold each of lines; RETURN 0 | |||||
| 2030 | # clear the digest; record the time for the throttle; RETURN 1 | |||||
| 2031 | # END FUNCTION | |||||
| 2032 | # --------------------------------------------------------------------------- | |||||
| 2033 | sub _send_email :Private { | |||||
| 2034 | my ($self, $sm, @lines) = @_; | |||||
| 2035 | ||||||
| 2036 | # Validate host and port before any eval so bad config croaks immediately | |||||
| 2037 | my $host = $sm->{'host'} || $DEFAULT_SMTP_HOST; | |||||
| 2038 | Carp::croak(ref($self), ": Invalid SMTP host: $host") | |||||
| 2039 | if $host =~ $RE_SAFE_HOST; | |||||
| 2040 | my $port = $sm->{'port'} || $DEFAULT_SMTP_PORT; | |||||
| 2041 | Carp::croak(ref($self), ": Invalid SMTP port: $port") | |||||
| 2042 | unless $port =~ $RE_PORT | |||||
| 2043 | && $port >= $MIN_PORT | |||||
| 2044 | && $port <= $MAX_PORT; | |||||
| 2045 | ||||||
| 2046 | my $dropped = $self->{_email_digest_dropped}; | |||||
| 2047 | my @body = ( | |||||
| 2048 | @{$self->{_email_digest} || []}, | |||||
| 2049 | ($dropped ? ("... and $dropped more " . (($dropped == 1) ? 'message' : 'messages')) : ()), | |||||
| 2050 | @lines, | |||||
| 2051 | ); | |||||
| 2052 | return 1 if(!@body); | |||||
| 2053 | ||||||
| 2054 | # Load mail modules lazily; called in an eval to handle delivery failures | |||||
| 2055 | my $deliver = sub { | |||||
| 2056 | require Email::Simple; | |||||
| 2057 | require Email::Sender::Simple; | |||||
| 2058 | require Email::Sender::Transport::SMTP; | |||||
| 2059 | ||||||
| 2060 | # Build the email object with sanitised headers | |||||
| 2061 | my $email = Email::Simple->new(''); | |||||
| 2062 | $email->header_set('to', _sanitize_email_header($sm->{'to'})); | |||||
| 2063 | $email->header_set('from', _sanitize_email_header($sm->{'from'} || $DEFAULT_FROM_ADDR)); | |||||
| 2064 | if(my $subject = $sm->{'subject'}) { | |||||
| 2065 | $email->header_set('subject', _sanitize_email_header($subject)); | |||||
| 2066 | } | |||||
| 2067 | $email->body_set(join("\n", @body)); | |||||
| 2068 | ||||||
| 2069 | my $transport = Email::Sender::Transport::SMTP->new({ | |||||
| 2070 | host => $host, | |||||
| 2071 | port => $port, | |||||
| 2072 | }); | |||||
| 2073 | # A class method, rather than the exported sendmail(), so that | |||||
| 2074 | # nothing is imported into this package | |||||
| 2075 | Email::Sender::Simple->send($email, { transport => $transport }); | |||||
| 2076 | }; | |||||
| 2077 | ||||||
| 2078 | # async: send from a child process, so that the log call doesn't wait | |||||
| 2079 | # for the SMTP conversation. Windows' fork is emulated with threads, | |||||
| 2080 | # and while perl is exiting (DESTROY's flush) the modules may be gone | |||||
| 2081 | if($sm->{'async'} && ($^O ne 'MSWin32') && (${^GLOBAL_PHASE} ne 'DESTRUCT')) { | |||||
| 2082 | _reap_email_children(); | |||||
| 2083 | my $pid = do { | |||||
| 2084 | 37 37 37 | 8779 26 94 | no autodie qw(fork); | |||
| 2085 | fork(); | |||||
| 2086 | }; | |||||
| 2087 | if(defined($pid) && ($pid == 0)) { | |||||
| 2088 | # The child: no END blocks, destructors or buffered output of | |||||
| 2089 | # the parent's must run here, so leave with _exit | |||||
| 2090 | my $ok = eval { $deliver->(); 1 }; | |||||
| 2091 | if(!$ok) { | |||||
| 2092 | # Copied first: entering the eval clears $@ | |||||
| 2093 | my $error = $@; | |||||
| 2094 | eval { Carp::carp("Failed to send email: $error") }; | |||||
| 2095 | } | |||||
| 2096 | POSIX::_exit($ok ? $EXIT_SENT : $EXIT_FAILED); | |||||
| 2097 | } | |||||
| 2098 | if(defined($pid)) { | |||||
| 2099 | push @email_children, $pid; | |||||
| 2100 | delete @{$self}{qw(_email_digest _email_digest_dropped)}; | |||||
| 2101 | $self->{_last_email_sent} = time(); | |||||
| 2102 | return 1; | |||||
| 2103 | } | |||||
| 2104 | # fork failed: send it here instead | |||||
| 2105 | } | |||||
| 2106 | ||||||
| 2107 | if(!eval { $deliver->(); 1 }) { | |||||
| 2108 | Carp::carp("Failed to send email: $@"); | |||||
| 2109 | if($sm->{'digest'}) { | |||||
| 2110 | $self->_hold_email($sm, $_) for @lines; | |||||
| 2111 | } | |||||
| 2112 | return 0; | |||||
| 2113 | } | |||||
| 2114 | ||||||
| 2115 | # Record send time for the throttle on success | |||||
| 2116 | delete @{$self}{qw(_email_digest _email_digest_dropped)}; | |||||
| 2117 | $self->{_last_email_sent} = time(); | |||||
| 2118 | return 1; | |||||
| 2119 | 37 37 37 | 6187 24 201 | } | |||
| 2120 | ||||||
| 2121 | # --------------------------------------------------------------------------- | |||||
| 2122 | # _reap_email_children -- collect the async sendmail children that finished | |||||
| 2123 | # | |||||
| 2124 | # Purpose: Stop finished children from being left as zombies. | |||||
| 2125 | # Entry: None. | |||||
| 2126 | # Exit: Returns nothing. | |||||
| 2127 | # Side effects: Reaps, without waiting, the children in @email_children | |||||
| 2128 | # that have exited, and forgets them. One already reaped by | |||||
| 2129 | # the program (e.g. by a SIGCHLD handler) is forgotten too. | |||||
| 2130 | # Notes: Called before each async send and by DESTROY. Children | |||||
| 2131 | # still running then are reaped by a later call, or when the | |||||
| 2132 | # program exits. | |||||
| 2133 | # --------------------------------------------------------------------------- | |||||
| 2134 | sub _reap_email_children :Private { | |||||
| 2135 | @email_children = grep { waitpid($_, POSIX::WNOHANG()) == 0 } @email_children; | |||||
| 2136 | return; | |||||
| 2137 | 37 37 37 | 5627 16 140 | } | |||
| 2138 | ||||||
| 2139 | # --------------------------------------------------------------------------- | |||||
| 2140 | # _hold_email -- keep a message body for the next email (sendmail digest) | |||||
| 2141 | # | |||||
| 2142 | # Purpose: With digest, messages that min_interval (or a failed send) | |||||
| 2143 | # would lose are sent with the next email instead. | |||||
| 2144 | # Entry: $self -- the logger object. | |||||
| 2145 | # $sm -- the sendmail hash (digest_max). | |||||
| 2146 | # $line -- the message's email body. | |||||
| 2147 | # Exit: Returns nothing. Holds $line, or once digest_max are held, | |||||
| 2148 | # only counts it, so a burst can't use unbounded memory. | |||||
| 2149 | # --------------------------------------------------------------------------- | |||||
| 2150 | sub _hold_email :Private { | |||||
| 2151 | my ($self, $sm, $line) = @_; | |||||
| 2152 | ||||||
| 2153 | my $held = $self->{_email_digest} ||= []; | |||||
| 2154 | if(scalar(@{$held}) < ($sm->{'digest_max'} // $DEFAULT_DIGEST_MAX)) { | |||||
| 2155 | push @{$held}, $line; | |||||
| 2156 | } else { | |||||
| 2157 | $self->{_email_digest_dropped}++; | |||||
| 2158 | } | |||||
| 2159 | return; | |||||
| 2160 | 37 37 37 | 6288 167 136 | } | |||
| 2161 | ||||||
| 2162 | # --------------------------------------------------------------------------- | |||||
| 2163 | # _validate_file_path -- validate and untaint a filesystem path | |||||
| 2164 | # | |||||
| 2165 | # Purpose: Ensure a caller-supplied path does not contain dangerous | |||||
| 2166 | # characters or directory-traversal sequences before it is | |||||
| 2167 | # passed to open(). | |||||
| 2168 | # Entry: $self -- the logger object (for error context in croak). | |||||
| 2169 | # $path -- the raw path string to validate. | |||||
| 2170 | # Exit: Returns the untainted capture (Perl taint-safe string). | |||||
| 2171 | # Croaks with a descriptive message if validation fails. | |||||
| 2172 | # Notes: Blocks the character set <, >, |, *, ?, ;, !, `, $, " | |||||
| 2173 | # and all C0 control characters, as well as ".." sequences. | |||||
| 2174 | # --------------------------------------------------------------------------- | |||||
| 2175 | sub _validate_file_path :Private { | |||||
| 2176 | my ($self, $path) = @_; | |||||
| 2177 | ||||||
| 2178 | # Block ".." path-traversal and all dangerous shell metacharacters | |||||
| 2179 | if($path =~ $RE_SAFE_PATH && $path !~ $RE_DOTDOT) { | |||||
| 2180 | return $1; # $1 is the untainted capture from RE_SAFE_PATH | |||||
| 2181 | } | |||||
| 2182 | Carp::croak(ref($self), ": Invalid file name: $path"); | |||||
| 2183 | 37 37 37 | 6117 49 245 | } | |||
| 2184 | ||||||
| 2185 | # --------------------------------------------------------------------------- | |||||
| 2186 | # _format_message -- expand a log-format string into a final log line | |||||
| 2187 | # | |||||
| 2188 | # Purpose: Centralise the repeated format-token substitution so that | |||||
| 2189 | # file, fd, and scalar-path backends all share one code path. | |||||
| 2190 | # Entry: $self -- the logger object (source of 'format' setting). | |||||
| 2191 | # $level -- log level string (e.g. 'debug'). | |||||
| 2192 | # $str -- the already-joined message string. | |||||
| 2193 | # $use_class -- 1 to include %class% in the default format, | |||||
| 2194 | # 0 to use the no-class format. | |||||
| 2195 | # $caller_file -- pre-resolved source file of the logging call. | |||||
| 2196 | # $caller_line -- pre-resolved source line of the logging call. | |||||
| 2197 | # $fields -- optional hashref of structured fields. | |||||
| 2198 | # $timestamp -- the formatted time of the log call, from | |||||
| 2199 | # _timestamp (computed here if undef). | |||||
| 2200 | # $format -- the backend's own format, or undef for the | |||||
| 2201 | # logger's 'format' (or the default). | |||||
| 2202 | # Exit: Returns the formatted log line (without trailing newline). | |||||
| 2203 | # Notes: %env_FOO% tokens are expanded with a // '' fallback so that | |||||
| 2204 | # missing environment variables expand silently to empty string. | |||||
| 2205 | # caller_file/caller_line are computed by _log at the correct | |||||
| 2206 | # stack depth (adjusted for the extra _high_priority frame on | |||||
| 2207 | # warn/error calls) so the reported location is always the | |||||
| 2208 | # caller's code, not an internal dispatch frame. | |||||
| 2209 | # | |||||
| 2210 | # Pseudocode: | |||||
| 2211 | # FUNCTION _format_message(self, level, str, use_class, caller_file, caller_line, fields, timestamp, format) | |||||
| 2212 | # timestamp = timestamp // _timestamp() | |||||
| 2213 | # format = format // self->{'format'} | |||||
| 2214 | # IF format eq 'json': | |||||
| 2215 | # Build hash: timestamp, level, message, file=caller_file, line=caller_line | |||||
| 2216 | # (+ class if subclass) | |||||
| 2217 | # (+ fields, with blessed values stringified, if any) | |||||
| 2218 | # RETURN _to_json(\%hash) | |||||
| 2219 | # [single compact line, character string, sorted keys] | |||||
| 2220 | # | |||||
| 2221 | # Choose default format template: | |||||
| 2222 | # use_class=1 â DEFAULT_FORMAT (includes %class%) | |||||
| 2223 | # use_class=0 â DEFAULT_FORMAT_NOCLASS | |||||
| 2224 | # Override with format if one was supplied (non-empty) | |||||
| 2225 | # | |||||
| 2226 | # Compute token values: | |||||
| 2227 | # message = str, plus the fields as logfmt key=value pairs if any, | |||||
| 2228 | # with each embedded line break followed by a tab, so | |||||
| 2229 | # continuation lines can't pass as new log entries | |||||
| 2230 | # ulevel = uc(level) | |||||
| 2231 | # class = blessed class if it is a subclass, else '' (base package) | |||||
| 2232 | # callstack = caller_file and caller_line | |||||
| 2233 | # timestamp = the timestamp argument | |||||
| 2234 | # | |||||
| 2235 | # Expand tokens in format string in a single pass (substituted values, | |||||
| 2236 | # including the message, are never rescanned for further tokens): | |||||
| 2237 | # %level% â ulevel | |||||
| 2238 | # %class% â class (may be empty) | |||||
| 2239 | # %message% â message | |||||
| 2240 | # %callstack% â callstack | |||||
| 2241 | # %timestamp% â timestamp | |||||
| 2242 | # %env_FOO% â $ENV{FOO} // '' (silent if env var unset) | |||||
| 2243 | # | |||||
| 2244 | # RETURN formatted line string | |||||
| 2245 | # END FUNCTION | |||||
| 2246 | # --------------------------------------------------------------------------- | |||||
| 2247 | sub _format_message :Private { | |||||
| 2248 | my ($self, $level, $str, $use_class, $caller_file, $caller_line, $fields, $timestamp, $format) = @_; | |||||
| 2249 | ||||||
| 2250 | $timestamp //= $self->_timestamp(); | |||||
| 2251 | $format //= $self->{'format'}; | |||||
| 2252 | ||||||
| 2253 | # 'json' is a magic format value: emit a compact JSON object per line | |||||
| 2254 | if(defined($format) && ($format eq 'json')) { | |||||
| 2255 | my $bclass = Scalar::Util::blessed($self); | |||||
| 2256 | my $class = ($bclass && $bclass ne __PACKAGE__) ? $bclass : undef; | |||||
| 2257 | my %obj = ( | |||||
| 2258 | timestamp => $timestamp, | |||||
| 2259 | level => $level, | |||||
| 2260 | message => $str, | |||||
| 2261 | file => $caller_file, | |||||
| 2262 | line => $caller_line + 0, | |||||
| 2263 | ); | |||||
| 2264 | $obj{class} = $class if defined($class); | |||||
| 2265 | if($fields) { | |||||
| 2266 | # Stringify objects, which would otherwise be encoded as null | |||||
| 2267 | $obj{fields} = { | |||||
| 2268 | map { $_ => (Scalar::Util::blessed($fields->{$_}) ? "$fields->{$_}" : $fields->{$_}) } keys %{$fields} | |||||
| 2269 | }; | |||||
| 2270 | } | |||||
| 2271 | # Characters out (not UTF-8 bytes): _write_line does the encoding | |||||
| 2272 | return _to_json(\%obj); | |||||
| 2273 | } | |||||
| 2274 | ||||||
| 2275 | # Select the appropriate default when no custom format is configured ('' is falsy) | |||||
| 2276 | my $default = $use_class ? $DEFAULT_FORMAT : $DEFAULT_FORMAT_NOCLASS; | |||||
| 2277 | $format = $format || $default; | |||||
| 2278 | ||||||
| 2279 | my $ulevel = uc($level); | |||||
| 2280 | ||||||
| 2281 | # Suppress the class name for the base package (only show for subclasses) | |||||
| 2282 | my $bclass = Scalar::Util::blessed($self); | |||||
| 2283 | my $class = ($bclass && $bclass ne __PACKAGE__) ? $bclass : ''; | |||||
| 2284 | ||||||
| 2285 | # Indent continuation lines so that a message such as | |||||
| 2286 | # "a\nERROR> [...] forged" can't pass as a separate log entry | |||||
| 2287 | my $message = $fields ? join(' ', grep { length } $str, _fields_text($fields)) : $str; | |||||
| 2288 | $message =~ s/\r\n?|\n/\n\t/g; | |||||
| 2289 | ||||||
| 2290 | my $callstack = "$caller_file $caller_line"; | |||||
| 2291 | ||||||
| 2292 | my %tokens = ( | |||||
| 2293 | level => $ulevel, | |||||
| 2294 | class => $class, | |||||
| 2295 | message => $message, | |||||
| 2296 | callstack => $callstack, | |||||
| 2297 | timestamp => $timestamp, | |||||
| 2298 | ); | |||||
| 2299 | ||||||
| 2300 | # Expand all tokens in one pass so substituted text (notably the message) | |||||
| 2301 | # is never rescanned; otherwise a message containing "%env_SECRET%" would | |||||
| 2302 | # leak the environment variable into the log | |||||
| 2303 | $format =~ s/%(?:(level|class|message|callstack|timestamp)|env_(\w+))%/ | |||||
| 2304 | defined($1) ? $tokens{$1} : ($ENV{$2} \/\/ '')/gex; | |||||
| 2305 | ||||||
| 2306 | return $format; | |||||
| 2307 | 37 37 37 | 11947 37 157 | } | |||
| 2308 | ||||||
| 2309 | # --------------------------------------------------------------------------- | |||||
| 2310 | # _log -- central dispatcher that routes a message to all active backends | |||||
| 2311 | # | |||||
| 2312 | # Purpose: Every public logging method ultimately calls _log. It checks | |||||
| 2313 | # the current level threshold, records the message in the | |||||
| 2314 | # internal history, then dispatches to the configured backend(s). | |||||
| 2315 | # Entry: $self -- the logger object. | |||||
| 2316 | # $level -- one of trace/debug/info/notice/warn/error/ | |||||
| 2317 | # critical/alert/emergency. | |||||
| 2318 | # @messages -- one or more message strings (or a single arrayref), | |||||
| 2319 | # optionally followed by a hashref of structured fields. | |||||
| 2320 | # Exit: Returns nothing (void). Croaks on configuration errors. | |||||
| 2321 | # Side effects: Appends to $self->{messages}. Passes the message to the | |||||
| 2322 | # backends (Log::Abstraction::Backend::*), which may write to a | |||||
| 2323 | # file, fd, array, syslog, journald, email, Log::Any or | |||||
| 2324 | # Log::Dispatch. May load Email::* modules. | |||||
| 2325 | # Notes: Enforced private: croaks if called from outside this package. | |||||
| 2326 | # The caller file/line is resolved past the _high_priority frame | |||||
| 2327 | # (warn/error) and any Log::Any frames, so it is the user's code. | |||||
| 2328 | # | |||||
| 2329 | # Pseudocode: | |||||
| 2330 | # FUNCTION _log(self, level, messages...) | |||||
| 2331 | # CROAK if caller package is not this package (private method guard) | |||||
| 2332 | # CROAK if level is not a recognised syslog level name | |||||
| 2333 | # RETURN early if syslog_values{level} > self->{'level'} (below threshold) | |||||
| 2334 | # | |||||
| 2335 | # IF more than one argument AND the last is an unblessed hashref: | |||||
| 2336 | # Pop it as the structured fields (a shallow copy; undef if empty) | |||||
| 2337 | # Flatten single-arrayref argument to a list; filter out undefs; join to $str | |||||
| 2338 | # IF redact: _redact $str (the parts become just $str) and the fields | |||||
| 2339 | # $text = $str plus the fields as logfmt key=value pairs (for backends | |||||
| 2340 | # with no field support: syslog, email, objects) | |||||
| 2341 | # Push { level, message, fields? } onto self->{messages} (always recorded); | |||||
| 2342 | # drop the oldest entries beyond max_messages | |||||
| 2343 | # Set $class = '' for base package, else the blessed class name | |||||
| 2344 | # Resolve caller file/line; format the timestamp once (_timestamp), | |||||
| 2345 | # shared by every file/fd backend | |||||
| 2346 | # render(format) = _format_message(..., format), cached per format; | |||||
| 2347 | # undef format means the logger's own | |||||
| 2348 | # Build the event: level, priority, message, parts, fields, text, the | |||||
| 2349 | # history entry, class, caller file/line, ctx, and closures for the | |||||
| 2350 | # private methods the backends need (render, write, send_email, | |||||
| 2351 | # hold_email, field_string) | |||||
| 2352 | # backends = self->{_backends}, or _build_backends() if not built yet | |||||
| 2353 | # FOR each backend (see _build_backends for which and in what order): | |||||
| 2354 | # IF backend->wants(event) (its own level, if any, lets it through): | |||||
| 2355 | # backend->emit(self, event) | |||||
| 2356 | # (each Log::Abstraction::Backend::* class documents what it does) | |||||
| 2357 | # END FUNCTION | |||||
| 2358 | # --------------------------------------------------------------------------- | |||||
| 2359 | sub _log :Private { | |||||
| 2360 | my ($self, $level, @messages) = @_; | |||||
| 2361 | ||||||
| 2362 | # Reject direct calls from outside this package (also enforced by :Private) | |||||
| 2363 | if(!(caller)[0]->isa(__PACKAGE__)) { | |||||
| 2364 | Carp::croak('Illegal Operation: _log is a private method'); | |||||
| 2365 | } | |||||
| 2366 | ||||||
| 2367 | # Logging must not disturb the caller's error state: code such as | |||||
| 2368 | # eval { ... }; if($@) { $log->debug(...); die $@ } relies on it, and | |||||
| 2369 | # the backends' own evals and I/O would otherwise reset $@ and $! | |||||
| 2370 | local ($@, $!); | |||||
| 2371 | ||||||
| 2372 | # Sanity-check the level (should not be reachable in normal use) | |||||
| 2373 | if(!defined($syslog_values{$level})) { | |||||
| 2374 | Carp::croak(ref($self), ": Invalid level '$level'"); | |||||
| 2375 | } | |||||
| 2376 | ||||||
| 2377 | # Drop messages that fall below the configured threshold | |||||
| 2378 | if($syslog_values{$level} > $self->{'level'}) { | |||||
| 2379 | return; | |||||
| 2380 | } | |||||
| 2381 | ||||||
| 2382 | # A trailing hashref after the message holds structured fields, e.g. | |||||
| 2383 | # $log->info('login', { user_id => 42 }). Copy it so that the caller | |||||
| 2384 | # changing it later doesn't rewrite the history | |||||
| 2385 | my $fields; | |||||
| 2386 | if((scalar(@messages) > 1) && (ref($messages[-1]) eq 'HASH')) { | |||||
| 2387 | $fields = pop @messages; | |||||
| 2388 | $fields = %{$fields} ? { %{$fields} } : undef; | |||||
| 2389 | } | |||||
| 2390 | ||||||
| 2391 | # Flatten a single arrayref argument to a plain list | |||||
| 2392 | if((scalar(@messages) == 1) && (ref($messages[0]) eq 'ARRAY')) { | |||||
| 2393 | @messages = @{$messages[0]}; | |||||
| 2394 | } | |||||
| 2395 | ||||||
| 2396 | # Remove any undef elements before joining | |||||
| 2397 | @messages = grep { defined } @messages; | |||||
| 2398 | my $str = join('', @messages); | |||||
| 2399 | chomp($str); | |||||
| 2400 | ||||||
| 2401 | # Redact before the message reaches the history or any backend. The | |||||
| 2402 | # regex runs over the joined message, so a match may span arguments; | |||||
| 2403 | # the CODE and object backends then get the one redacted string | |||||
| 2404 | if(my $redact = $self->{'redact'}) { | |||||
| 2405 | $str = _redact($redact, $str); | |||||
| 2406 | @messages = ($str); | |||||
| 2407 | $fields = _redact($redact, $fields) if($fields); | |||||
| 2408 | } | |||||
| 2409 | ||||||
| 2410 | # Backends with no notion of fields get them appended as text | |||||
| 2411 | my $fields_text = $fields ? _fields_text($fields) : undef; | |||||
| 2412 | my $text = $fields ? join(' ', grep { length } $str, $fields_text) : $str; | |||||
| 2413 | ||||||
| 2414 | # The entry recorded by the history and the array backends | |||||
| 2415 | my @entry = (level => $level, message => $str, ($fields ? (fields => $fields) : ())); | |||||
| 2416 | ||||||
| 2417 | # Record in the internal message history regardless of backend, | |||||
| 2418 | # discarding the oldest entries beyond max_messages | |||||
| 2419 | my $history = $self->{messages}; | |||||
| 2420 | push @{$history}, { @entry }; | |||||
| 2421 | if(defined(my $max = $self->{'max_messages'})) { | |||||
| 2422 | splice(@{$history}, 0, scalar(@{$history}) - $max) if(scalar(@{$history}) > $max); | |||||
| 2423 | } | |||||
| 2424 | ||||||
| 2425 | # Compute class once; suppress the package name for base-class instances | |||||
| 2426 | my $class = Scalar::Util::blessed($self) || $self; | |||||
| 2427 | if($class eq __PACKAGE__) { | |||||
| 2428 | $class = ''; | |||||
| 2429 | } | |||||
| 2430 | ||||||
| 2431 | # Resolve caller file/line at the correct stack depth. | |||||
| 2432 | # For trace/debug/info/notice: _log â public_method â user â depth=1 | |||||
| 2433 | # For warn/error: _log â _high_priority â public_method â user â depth=2 | |||||
| 2434 | # Frames inside Log::Any (its proxy and our adapter) are skipped too, so | |||||
| 2435 | # messages routed through Log::Any report the user's code. So are those | |||||
| 2436 | # of the Log::Abstraction that forwarded a message here (see the LogAny | |||||
| 2437 | # and LogDispatch backends) | |||||
| 2438 | my $depth = ((caller(1))[3] // '') =~ /::_high_priority$/ ? 2 : 1; | |||||
| 2439 | my $skip = $Log::Abstraction::Backend::FORWARDING ? qr/^Log::(?:Any|Abstraction|Dispatch)(?:::|$)/ : qr/^Log::Any(?:::|$)/; | |||||
| 2440 | while((caller($depth + 1))[0] && (((caller($depth))[0] // '') =~ $skip)) { | |||||
| 2441 | $depth++; | |||||
| 2442 | } | |||||
| 2443 | my $caller_file = (caller($depth))[1]; | |||||
| 2444 | my $caller_line = (caller($depth))[2]; | |||||
| 2445 | ||||||
| 2446 | # One timestamp per message, so that every backend shows the same time | |||||
| 2447 | my $timestamp = $self->_timestamp(); | |||||
| 2448 | ||||||
| 2449 | # Format the message for a backend: $format is its own format, or undef | |||||
| 2450 | # for the logger's. Each format is only rendered once per message | |||||
| 2451 | my $use_class = ($class ne '') ? 1 : 0; | |||||
| 2452 | my %rendered; | |||||
| 2453 | my $render = sub { | |||||
| 2454 | my ($format) = @_; | |||||
| 2455 | return $rendered{$format // ''} //= $self->_format_message( | |||||
| 2456 | $level, $str, $use_class, $caller_file, $caller_line, $fields, $timestamp, $format, | |||||
| 2457 | ); | |||||
| 2458 | }; | |||||
| 2459 | ||||||
| 2460 | # What a backend needs to know about the message, and closures for | |||||
| 2461 | # the private methods it needs (see Log::Abstraction::Backend) | |||||
| 2462 | my %event = ( | |||||
| 2463 | level => $level, | |||||
| 2464 | priority => $syslog_values{$level}, | |||||
| 2465 | message => $str, | |||||
| 2466 | parts => \@messages, | |||||
| 2467 | fields => $fields, | |||||
| 2468 | fields_text => $fields_text, | |||||
| 2469 | text => $text, | |||||
| 2470 | entry => \@entry, | |||||
| 2471 | class => Scalar::Util::blessed($self) || __PACKAGE__, | |||||
| 2472 | file => $caller_file, | |||||
| 2473 | line => $caller_line, | |||||
| 2474 | ctx => $self->{ctx}, | |||||
| 2475 | render => $render, | |||||
| 2476 | write => sub { | |||||
| 2477 | my ($target, $line) = @_; | |||||
| 2478 | $target = $self->_validate_file_path($target) if(!ref($target)); | |||||
| 2479 | $self->_write_line($target, $line); | |||||
| 2480 | }, | |||||
| 2481 | send_email => sub { $self->_send_email(@_) }, | |||||
| 2482 | hold_email => sub { $self->_hold_email(@_) }, | |||||
| 2483 | field_string => sub { _field_string(@_) }, | |||||
| 2484 | ); | |||||
| 2485 | ||||||
| 2486 | # Pass the message to every backend whose own level it passes. A bare | |||||
| 2487 | # object (not made by new()) builds them now | |||||
| 2488 | my $backends = $self->{_backends} //= $self->_build_backends(); | |||||
| 2489 | for my $backend (@{$backends}) { | |||||
| 2490 | $backend->emit($self, \%event) if($backend->wants(\%event)); | |||||
| 2491 | } | |||||
| 2492 | 37 37 37 | 14004 12 156 | } | |||
| 2493 | ||||||
| 2494 | # --------------------------------------------------------------------------- | |||||
| 2495 | # _high_priority -- common handler for warn(), error() and the levels above | |||||
| 2496 | # | |||||
| 2497 | # Purpose: Extracts the warning/error text from a variety of argument | |||||
| 2498 | # forms (plain list, named 'warning' key, or arrayref value), | |||||
| 2499 | # then dispatches to _log and optionally to Carp. | |||||
| 2500 | # Entry: $self -- the logger object. | |||||
| 2501 | # $level -- 'warn', 'error', 'critical', 'alert' or 'emergency'. | |||||
| 2502 | # @_ -- remaining arguments in any of the accepted forms. | |||||
| 2503 | # Exit: Returns nothing (void). | |||||
| 2504 | # Side effects: Calls _log, which appends to $self->{messages} and writes to | |||||
| 2505 | # configured backends. May call Carp::carp or Carp::croak. | |||||
| 2506 | # Notes: The duplicated extraction logic that appeared in earlier | |||||
| 2507 | # versions has been collapsed into a single if/else block. | |||||
| 2508 | # | |||||
| 2509 | # Pseudocode: | |||||
| 2510 | # FUNCTION _high_priority(self, level, args...) | |||||
| 2511 | # RETURN early if no args supplied | |||||
| 2512 | # | |||||
| 2513 | # IF more than one arg AND the last is an unblessed hashref: | |||||
| 2514 | # Pop it as the structured fields | |||||
| 2515 | # | |||||
| 2516 | # Attempt to parse args as named-parameter form via Params::Get (in eval) | |||||
| 2517 | # | |||||
| 2518 | # IF named 'warning' key found in result: | |||||
| 2519 | # Extract warning value; RETURN if value is undef | |||||
| 2520 | # IF value is an arrayref: join defined elements into a string | |||||
| 2521 | # ELSE (plain list form): | |||||
| 2522 | # Join defined elements of @_ into a string | |||||
| 2523 | # RETURN if resulting string is empty | |||||
| 2524 | # | |||||
| 2525 | # IF called as a class method (self is a package name, not an object): | |||||
| 2526 | # IF error level or above: CROAK with warning text; RETURN | |||||
| 2527 | # CARP with warning text; RETURN | |||||
| 2528 | # | |||||
| 2529 | # Call self->_log(level, warning, fields?) | |||||
| 2530 | # IF redact: _redact the warning text, for Carp below | |||||
| 2531 | # | |||||
| 2532 | # no_backend = no logger, array, file or fd configured | |||||
| 2533 | # | |||||
| 2534 | # IF error level or above: | |||||
| 2535 | # IF croak_on_error flag set OR no_backend: | |||||
| 2536 | # CROAK with warning text | |||||
| 2537 | # | |||||
| 2538 | # IF (carp_on_warn flag set OR no_backend) AND level passes threshold: | |||||
| 2539 | # CARP with warning text | |||||
| 2540 | # END FUNCTION | |||||
| 2541 | # --------------------------------------------------------------------------- | |||||
| 2542 | sub _high_priority :Private { | |||||
| 2543 | my $self = shift; | |||||
| 2544 | my $level = shift; # 'warn', 'error', 'critical', 'alert' or 'emergency' | |||||
| 2545 | ||||||
| 2546 | # Preserve the caller's $@ and $! (see _log); a croak from here still | |||||
| 2547 | # reaches the caller, as die sets $@ after the stack has unwound | |||||
| 2548 | local ($@, $!); | |||||
| 2549 | ||||||
| 2550 | # Nothing to log if no arguments supplied | |||||
| 2551 | return if(scalar(@_) == 0); | |||||
| 2552 | ||||||
| 2553 | # A trailing hashref after the message holds structured fields. A lone | |||||
| 2554 | # hashref is the warn({ warning => ... }) form, not fields | |||||
| 2555 | my @fields; | |||||
| 2556 | if((scalar(@_) > 1) && (ref($_[-1]) eq 'HASH')) { | |||||
| 2557 | @fields = (pop @_); | |||||
| 2558 | } | |||||
| 2559 | ||||||
| 2560 | # Try to interpret arguments as warn(warning => VALUE) named form | |||||
| 2561 | my $params; | |||||
| 2562 | eval { $params = Params::Get::get_params('warning', @_) }; | |||||
| 2563 | ||||||
| 2564 | # Determine the final warning string from whichever form was passed | |||||
| 2565 | my $warning; | |||||
| 2566 | if($params && ref($params) eq 'HASH' && exists($params->{warning})) { | |||||
| 2567 | # Named form: warn({ warning => ... }) or warn(warning => ...) | |||||
| 2568 | $warning = $params->{warning}; | |||||
| 2569 | return unless defined($warning); | |||||
| 2570 | if(ref($warning) eq 'ARRAY') { | |||||
| 2571 | # Arrayref value: join defined elements | |||||
| 2572 | $warning = join('', grep { defined } @{$warning}); | |||||
| 2573 | } | |||||
| 2574 | } else { | |||||
| 2575 | # Plain list form: warn('text', 'more text', ...) | |||||
| 2576 | $warning = join('', grep { defined } @_); | |||||
| 2577 | return unless length($warning); | |||||
| 2578 | } | |||||
| 2579 | ||||||
| 2580 | # If called as a class method (on this package or a subclass) rather | |||||
| 2581 | # than on an instance, use Carp directly | |||||
| 2582 | if(!ref($self)) { | |||||
| 2583 | if($syslog_values{$level} <= $ERROR) { | |||||
| 2584 | Carp::croak($warning); | |||||
| 2585 | } | |||||
| 2586 | Carp::carp($warning); | |||||
| 2587 | return; | |||||
| 2588 | } | |||||
| 2589 | ||||||
| 2590 | # Log the message through the normal dispatch path | |||||
| 2591 | $self->_log($level, $warning, @fields); | |||||
| 2592 | ||||||
| 2593 | # What Carp shows must be redacted too (_log redacts its own copy) | |||||
| 2594 | $warning = _redact($self->{'redact'}, $warning) if($self->{'redact'}); | |||||
| 2595 | ||||||
| 2596 | # A top-level file or fd counts as a backend, as do logger and array | |||||
| 2597 | my $no_backend = !defined($self->{'logger'}) && !defined($self->{'array'}) | |||||
| 2598 | && !$self->{'file'} && !$self->{'fd'}; | |||||
| 2599 | ||||||
| 2600 | # Optionally escalate to Carp for error-level messages | |||||
| 2601 | if($syslog_values{$level} <= $ERROR) { | |||||
| 2602 | if($self->{'croak_on_error'} || $no_backend) { | |||||
| 2603 | Carp::croak($warning); | |||||
| 2604 | } | |||||
| 2605 | } | |||||
| 2606 | ||||||
| 2607 | # Optionally also emit a Carp::carp, but only for a message that passed | |||||
| 2608 | # the level threshold | |||||
| 2609 | if(($self->{'carp_on_warn'} || $no_backend) | |||||
| 2610 | && ($syslog_values{$level} <= $self->{'level'})) { | |||||
| 2611 | Carp::carp($warning); | |||||
| 2612 | } | |||||
| 2613 | 37 37 37 | 9887 20 125 | } | |||
| 2614 | ||||||
| 2615 - 2690 | =head2 level
my $current = $logger->level();
$logger->level('debug');
Get or set the minimum logging level. When setting, returns C<$self> to
allow method chaining. When getting, returns the current level as an
integer (per the syslog numeric scale; lower numbers are higher priority).
=head3 Arguments
=over 4
=item * C<$level> (optional)
A level name string: C<trace>, C<debug>, C<info>, C<notice>, C<warn>/C<warning>,
or C<error>. Case-insensitive. Omit to perform a pure get.
=back
=head3 Returns
In getter mode: an integer in the range 0 (emergency) to 7 (debug/trace).
In setter mode: C<$self> (to allow chaining), or C<undef>, after a
C<Carp::carp>, if the level name is not recognised; the level is then
unchanged. A false argument (C<undef>, C<''> or C<0>) is a get, not a set,
so levels are set by name.
=head3 Side Effects
When setting, updates C<$self-E<gt>{level}>.
=head3 Example
$logger->level('debug');
my $n = $logger->level(); # e.g. 7
# Method chaining
$logger->level('info')->info('Now at info level');
=head3 API SPECIFICATION
=head4 Input
{
level => { type => 'string', regex => qr/^(trace|debug|info(?:rmational)?|notice|warn(?:ing)?|err(?:or)?|crit(?:ical)?|fatal|alert|emerg(?:ency)?|panic)$/i, optional => 1 },
}
=head4 Output
Getter: { type => 'integer', min => 0, max => 7 }
Setter: { type => 'object', class => 'Log::Abstraction' }
=head3 MESSAGES
Warning Meaning / Action
---------------------------------------- ------------------------------------------
"<class>: invalid syslog level '<l>'" The supplied level name is not recognised.
Use trace/debug/info/notice/warn/error.
=head3 PSEUDOCODE
FUNCTION level(self, level?)
IF level argument supplied:
CARP and RETURN undef if level is not a recognised syslog name
Store syslog_values{level} in self->{'level'}
RETURN self (allows method chaining)
ELSE (getter mode):
RETURN self->{'level'} (current numeric threshold)
END FUNCTION
=cut | |||||
| 2691 | ||||||
| 2692 | sub level { | |||||
| 2693 | 262 | 5126 | my ($self, $level) = @_; | |||
| 2694 | ||||||
| 2695 | 262 | 131 | if($level) { | |||
| 2696 | # Setter path: validate, store and return $self for chaining. | |||||
| 2697 | # Names are case-insensitive, as in new() | |||||
| 2698 | 239 | 154 | if(!defined($syslog_values{lc($level)})) { | |||
| 2699 | 2 | 4 | Carp::carp(ref($self), ": invalid syslog level '$level'"); | |||
| 2700 | 2 | 2 | return; # undef signals the caller that validation failed | |||
| 2701 | } | |||||
| 2702 | 237 | 112 | $self->{'level'} = $syslog_values{lc($level)}; | |||
| 2703 | 237 | 123 | return $self; | |||
| 2704 | } | |||||
| 2705 | ||||||
| 2706 | # Getter path: return the numeric threshold | |||||
| 2707 | return Return::Set::set_return( | |||||
| 2708 | 23 | 495 | $self->{'level'}, | |||
| 2709 | { 'type' => 'integer', 'min' => 0, 'max' => 7 }, | |||||
| 2710 | ); | |||||
| 2711 | } | |||||
| 2712 | ||||||
| 2713 - 2774 | =head2 Level detection methods
=over 4
=item is_trace
=item is_debug
=item is_info
=item is_notice
=item is_warn
=item is_error
=item is_critical
=item is_alert
=item is_emergency
=back
if($logger->is_debug()) { ... }
Each returns a true value when a message logged with the method of the same
name (C<is_warn> for C<warn()>) would pass the logger's level threshold, so
that expensive message-building can be skipped. They follow the current
threshold, including changes made with L</level>. As with the levels
themselves, C<is_trace> equals C<is_debug>. Provided for compatibility with
L<Log::Any>.
=head3 Arguments
None.
=head3 Returns
C<1> if messages at that level would be emitted; C<0> otherwise.
=head3 Example
if($logger->is_debug()) {
$logger->debug('Expensive diagnostic: ' . Dumper(\%state));
}
$logger->level('warning');
$logger->is_warn(); # 1
$logger->is_info(); # 0
=head3 API SPECIFICATION
=head4 Input
{} (no arguments)
=head4 Output
{ type => 'boolean' }
=cut | |||||
| 2775 | ||||||
| 2776 | # Build is_trace, is_debug, ... is_emergency. Each is true when its level's | |||||
| 2777 | # syslog number is within the threshold (a lower number is more severe) | |||||
| 2778 | for my $level (qw(trace debug info notice warn error critical alert emergency)) { | |||||
| 2779 | my $threshold = $syslog_values{$level}; | |||||
| 2780 | 37 37 37 | 7818 18 7724 | no strict 'refs'; | |||
| 2781 | *{"is_$level"} = sub { | |||||
| 2782 | 269 | 18229 | my $self = $_[0]; | |||
| 2783 | 269 | 358 | return (defined($self->{'level'}) && ($self->{'level'} >= $threshold)) ? 1 : 0; | |||
| 2784 | }; | |||||
| 2785 | } | |||||
| 2786 | ||||||
| 2787 - 2825 | =head2 messages
my $aref = $logger->messages();
Returns a reference to a shallow copy of all messages emitted through this
logger since it was created (or since the last clone).
=head3 Arguments
None.
=head3 Returns
An array reference of hashrefs, each with keys C<level> (string) and
C<message> (string), and C<fields> (hashref) when the message was logged with
L</Structured fields>.
=head3 Side Effects
None. The returned array is a copy; modifying it does not affect the
internal history.
=head3 Example
$logger->info('hello');
my $msgs = $logger->messages();
# $msgs->[0] = { level => 'info', message => 'hello' }
=head3 API SPECIFICATION
=head4 Input
{} (no arguments)
=head4 Output
{ type => 'arrayref', element_type => { level => 'string', message => 'string', fields => 'hashref?' } }
=cut | |||||
| 2826 | ||||||
| 2827 | sub messages { | |||||
| 2828 | 83 | 4503 | my $self = $_[0]; | |||
| 2829 | ||||||
| 2830 | 83 83 | 44 143 | return [ @{$self->{messages}} ]; | |||
| 2831 | } | |||||
| 2832 | ||||||
| 2833 - 2874 | =head2 flush
$logger->flush();
Sends, now, the messages that a C<sendmail> backend with C<digest> is
holding back because of C<min_interval> (see L</Email digests>), whether or
not the interval has passed. Does nothing if none are held. Called
automatically when the logger is destroyed.
=head3 Arguments
None.
=head3 Returns
The logger, for method chaining.
=head3 Side Effects
May send an email, which starts the C<min_interval> interval again. A
delivery failure is carped and the messages stay held. With C<async>, the
email is sent by a child process and the messages are no longer held: a
failure is carped by the child, and the messages are lost. Croaks if the
C<sendmail> C<host> or C<port> is invalid.
=head3 Example
$logger->error('disk full'); # emailed
$logger->error('disk still full'); # held: within min_interval
$logger->flush(); # emailed now
=head3 API SPECIFICATION
=head4 Input
{} (no arguments)
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=cut | |||||
| 2875 | ||||||
| 2876 | sub flush { | |||||
| 2877 | 0 | 0 | my $self = $_[0]; | |||
| 2878 | ||||||
| 2879 | # Preserve the caller's $@ and $! (see _log) | |||||
| 2880 | 0 | 0 | local ($@, $!); | |||
| 2881 | ||||||
| 2882 | 0 | 0 | my $sm = (ref($self->{'logger'}) eq 'HASH') ? $self->{'logger'}->{'sendmail'} : undef; | |||
| 2883 | 0 | 0 | if($sm && $self->{_email_digest}) { | |||
| 2884 | 0 | 0 | $self->_send_email($sm); | |||
| 2885 | } | |||||
| 2886 | 0 | 0 | return $self; | |||
| 2887 | } | |||||
| 2888 | ||||||
| 2889 - 2933 | =head2 reopen
$logger->reopen();
Closes the log files the logger holds open, so that the next message opens
them again. Log files written by path (see L</File rotation>) are kept open
between messages; call this after something outside the program has renamed,
moved or truncated them. It isn't usually needed: a file that has been
renamed or deleted is noticed on the next write, a C<SIGHUP> reopens every
logger's files (except on Windows, see L</logrotate>), and every file is
reopened when C<reopen_interval> has passed (unless it is C<-1>). File
handles passed as C<fd> are not closed. It does nothing if no files are
open.
A file is also closed when writing to it fails (e.g. the disk is full), so
that the next message opens it again.
A program that sets its own C<$SIG{HUP}> after logging has started replaces
the module's handler, and can call this from its own:
$SIG{HUP} = sub { $logger->reopen(); reload_config() };
=head3 Arguments
None.
=head3 Returns
The logger, for method chaining.
=head3 Side Effects
Closes the logger's log files.
=head3 API SPECIFICATION
=head4 Input
{} (no arguments)
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=cut | |||||
| 2934 | ||||||
| 2935 | sub reopen { | |||||
| 2936 | 5 | 260 | my $self = $_[0]; | |||
| 2937 | ||||||
| 2938 | # Preserve the caller's $@ and $! (see _log) | |||||
| 2939 | 5 | 6 | local ($@, $!); | |||
| 2940 | ||||||
| 2941 | 5 | 4 | $self->_close_files(); | |||
| 2942 | 5 | 8 | return $self; | |||
| 2943 | } | |||||
| 2944 | ||||||
| 2945 - 2997 | =head2 trace
$logger->trace(@messages);
$logger->trace(\@messages);
Logs a message at C<trace> level. syslog has no priority below debug, so
C<trace> shares C<debug>'s threshold: trace messages are emitted whenever
debug messages are, and are sent to syslog and journald as debug. The
message is dropped silently when the configured level is above C<debug>.
=head3 Arguments
=over 4
=item * C<@messages>
One or more strings, or a single array reference. All elements are joined
without a separator before storage. May be followed by a hashref of
L</Structured fields>.
=back
=head3 Returns
C<$self>, to allow method chaining.
=head3 Side Effects
Appends to the internal message history and dispatches to configured backends.
=head3 Example
$logger->trace('entering sub foo, args=', join(',', @args));
# Chaining
$logger->trace('start')->debug('details')->info('summary');
=head3 API SPECIFICATION
=head4 Input
{ messages => { type => [ 'arrayref', 'scalar' ] } }
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=head3 MESSAGES
Croaks if the configured backend is misconfigured, and carps if delivery
fails; see the second table under L</new>'s MESSAGES.
=cut | |||||
| 2998 | ||||||
| 2999 | sub trace { | |||||
| 3000 | 29 | 109 | my $self = shift; | |||
| 3001 | 29 | 43 | $self->_log('trace', @_); | |||
| 3002 | 29 | 68 | return $self; | |||
| 3003 | } | |||||
| 3004 | ||||||
| 3005 - 3050 | =head2 debug
$logger->debug(@messages);
$logger->debug(\@messages);
Logs a message at C<debug> level.
=head3 Arguments
=over 4
=item * C<@messages>
One or more strings, or a single array reference, optionally followed by
a hashref of L</Structured fields>.
=back
=head3 Returns
C<$self>, to allow method chaining.
=head3 Side Effects
Appends to the internal message history and dispatches to configured backends.
=head3 Example
$logger->debug('Query took ', $elapsed, 'ms');
=head3 API SPECIFICATION
=head4 Input
{ messages => { type => [ 'arrayref', 'scalar' ] } }
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=head3 MESSAGES
Croaks if the configured backend is misconfigured, and carps if delivery
fails; see the second table under L</new>'s MESSAGES.
=cut | |||||
| 3051 | ||||||
| 3052 | sub debug { | |||||
| 3053 | 10387 | 8861 | my $self = shift; | |||
| 3054 | 10387 | 6076 | $self->_log('debug', @_); | |||
| 3055 | 10371 | 5246 | return $self; | |||
| 3056 | } | |||||
| 3057 | ||||||
| 3058 - 3103 | =head2 info
$logger->info(@messages);
$logger->info(\@messages);
Logs a message at C<info> level.
=head3 Arguments
=over 4
=item * C<@messages>
One or more strings, or a single array reference, optionally followed by
a hashref of L</Structured fields>.
=back
=head3 Returns
C<$self>, to allow method chaining.
=head3 Side Effects
Appends to the internal message history and dispatches to configured backends.
=head3 Example
$logger->info('Server started on port ', $port);
=head3 API SPECIFICATION
=head4 Input
{ messages => { type => [ 'arrayref', 'scalar' ] } }
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=head3 MESSAGES
Croaks if the configured backend is misconfigured, and carps if delivery
fails; see the second table under L</new>'s MESSAGES.
=cut | |||||
| 3104 | ||||||
| 3105 | sub info { | |||||
| 3106 | 337 | 8623 | my $self = shift; | |||
| 3107 | 337 | 304 | $self->_log('info', @_); | |||
| 3108 | 337 | 1499 | return $self; | |||
| 3109 | } | |||||
| 3110 | ||||||
| 3111 - 3157 | =head2 notice
$logger->notice(@messages);
$logger->notice(\@messages);
Logs a message at C<notice> level (higher priority than C<info>, lower than
C<warn>).
=head3 Arguments
=over 4
=item * C<@messages>
One or more strings, or a single array reference, optionally followed by
a hashref of L</Structured fields>.
=back
=head3 Returns
C<$self>, to allow method chaining.
=head3 Side Effects
Appends to the internal message history and dispatches to configured backends.
=head3 Example
$logger->notice('Configuration reloaded');
=head3 API SPECIFICATION
=head4 Input
{ messages => { type => [ 'arrayref', 'scalar' ] } }
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=head3 MESSAGES
Croaks if the configured backend is misconfigured, and carps if delivery
fails; see the second table under L</new>'s MESSAGES.
=cut | |||||
| 3158 | ||||||
| 3159 | sub notice { | |||||
| 3160 | 42 | 1990 | my $self = shift; | |||
| 3161 | 42 | 53 | $self->_log('notice', @_); | |||
| 3162 | 41 | 52 | return $self; | |||
| 3163 | } | |||||
| 3164 | ||||||
| 3165 - 3237 | =head2 warn
$logger->warn(@messages);
$logger->warn(\@messages);
$logger->warn(warning => $text);
$logger->warn({ warning => $text });
$logger->warn(warning => \@parts);
$logger->warn($text, \%fields);
Logs a warning message. Also dispatches to syslog and/or email backends
when those are configured. Falls back to C<Carp::carp> when no backend
(C<logger>, C<array>, C<file> or C<fd>) is set. The C<Carp::carp> (whether
from C<carp_on_warn> or the fallback) only happens when the message passes
the level threshold.
Called as a class method (C<Log::Abstraction-E<gt>warn(...)>, or on a
subclass), it calls C<Carp::carp> directly.
A C<warn()> call with an empty or all-undef argument list is a silent no-op.
=head3 Arguments
=over 4
=item * C<@messages>
A plain list of strings joined without separator, B<or> a named C<warning>
parameter whose value may be a string or an array reference of strings.
Either form may be followed by a hashref of L</Structured fields>, e.g.
C<warn('Slow query', { ms =E<gt> 1250 })>.
=back
=head3 Returns
C<$self>, to allow method chaining.
=head3 Side Effects
Appends to internal message history. Writes to all configured backends.
May call C<Carp::carp> if C<carp_on_warn> is set or no backend is active.
=head3 Example
$logger->warn('Disk usage is high');
$logger->warn(warning => 'Connection reset', ' retrying');
$logger->warn({ warning => ['Part A', 'Part B'] });
=head3 API SPECIFICATION
=head4 Input
# Named form
{ warning => { type => [ 'scalar', 'arrayref' ] } }
# Plain-list form
{ messages => { type => 'arrayref' } }
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=head3 MESSAGES
(the warning text itself) Carped if carp_on_warn is set, or if no
backend (logger, array, file or fd) is
configured, provided the warning passes
the level threshold. Also carped when
called as a class method.
Backend misconfiguration and delivery failures are reported as described
in the second table under L</new>'s MESSAGES.
=cut | |||||
| 3238 | ||||||
| 3239 | sub warn { | |||||
| 3240 | 135 | 5297 | my $self = shift; | |||
| 3241 | ||||||
| 3242 | # Empty argument list is a documented no-op | |||||
| 3243 | 135 | 581 | if(scalar(@_) > 0) { | |||
| 3244 | 131 | 138 | $self->_high_priority('warn', @_); | |||
| 3245 | } | |||||
| 3246 | 135 | 302 | return $self; | |||
| 3247 | } | |||||
| 3248 | ||||||
| 3249 - 3301 | =head2 error
$logger->error(@messages);
$logger->error(warning => $text);
$logger->error($text, \%fields);
Logs an error-level message. Behaves identically to C<warn()> but at the
C<error> level, which triggers C<Carp::croak> if C<croak_on_error> is set
or no backend (C<logger>, C<array>, C<file> or C<fd>) is set. Called as a
class method, it calls C<Carp::croak> directly.
=head3 Arguments
Same argument forms as C<warn()>.
=head3 Returns
C<$self>, to allow method chaining. Note: if C<croak_on_error> is set, the
method never returns -- execution unwinds via C<Carp::croak>.
=head3 Side Effects
Same as C<warn()> plus optional C<Carp::croak> escalation.
=head3 Example
$logger->error('Fatal: database unavailable');
=head3 API SPECIFICATION
=head4 Input
{ warning => { type => [ 'scalar', 'arrayref' ], optional => 1 } }
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=head3 MESSAGES
Croak Meaning / Action
---------------------------------------- ------------------------------------------
(the error message text itself) croak_on_error is set, or no backend
(logger, array, file or fd) is
configured, or error() was called as a
class method. The call stack is unwound.
(the error message text itself), as a carp_on_warn is set and croak_on_error
carp is not.
Backend misconfiguration and delivery failures are reported as described
in the second table under L</new>'s MESSAGES.
=cut | |||||
| 3302 | ||||||
| 3303 | sub error { | |||||
| 3304 | 68 | 3946 | my $self = shift; | |||
| 3305 | 68 | 73 | $self->_high_priority('error', @_); | |||
| 3306 | 58 | 50 | return $self; | |||
| 3307 | } | |||||
| 3308 | ||||||
| 3309 - 3346 | =head2 fatal
$logger->fatal(@messages);
Synonym for C<error()>. Provided for compatibility with logging frameworks
that use C<fatal> as the highest-severity level name.
=head3 Arguments
Same as C<error()>.
=head3 Returns
C<$self>.
=head3 Side Effects
Same as C<error()>.
=head3 Example
$logger->fatal('Unrecoverable state; aborting');
=head3 API SPECIFICATION
=head4 Input
{ warning => { type => [ 'scalar', 'arrayref' ], optional => 1 } }
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=head3 MESSAGES
Same as C<error()>.
=cut | |||||
| 3347 | ||||||
| 3348 | sub fatal { | |||||
| 3349 | 11 | 162 | my $self = shift; | |||
| 3350 | 11 | 14 | $self->_high_priority('error', @_); | |||
| 3351 | 8 | 4 | return $self; | |||
| 3352 | } | |||||
| 3353 | ||||||
| 3354 - 3417 | =head2 Methods above error
=over 4
=item critical
=item alert
=item emergency
=back
$logger->critical(@messages);
$logger->alert(warning => $text);
$logger->emergency($text, \%fields);
Log a message at a level more severe than C<error>:
Method Level syslog Priority
---------- ---------- ------- --------
critical critical crit 2
alert alert alert 1
emergency emergency emerg 0
=head3 Arguments
C<critical>, C<alert> and C<emergency> take the same argument forms as
C<warn()>.
=head3 Returns
C<$self>, to allow method chaining (unless they croak; see below).
=head3 Side Effects
These behave like C<error()>, at a more severe level: C<croak_on_error>, or
having no backend, makes them C<Carp::croak>, and C<carp_on_warn> makes them
C<Carp::carp>. The level string passed to backends is the method name
(C<critical>, C<alert> or C<emergency>, upper-cased in text formats); syslog
gets C<crit>, C<alert> or C<emerg>, and journald C<PRIORITY> 2, 1 or 0. An
object logger without the method (such as L<Log::Log4perl>) is called with
C<fatal>, or C<error> if it has no C<fatal> either.
=head3 Example
$logger->critical('Disk 95% full', { mount => '/var' });
$logger->alert('Primary database unreachable');
$logger->emergency('Data corruption detected; shutting down');
=head3 API SPECIFICATION
=head4 Input
{ warning => { type => [ 'scalar', 'arrayref' ], optional => 1 } }
=head4 Output
{ type => 'object', class => 'Log::Abstraction' }
=head3 MESSAGES
Same as C<error()>.
=cut | |||||
| 3418 | ||||||
| 3419 | sub critical { | |||||
| 3420 | 26 | 2208 | my $self = shift; | |||
| 3421 | 26 | 29 | $self->_high_priority('critical', @_); | |||
| 3422 | 22 | 188 | return $self; | |||
| 3423 | } | |||||
| 3424 | ||||||
| 3425 | sub alert { | |||||
| 3426 | 24 | 2324 | my $self = shift; | |||
| 3427 | 24 | 23 | $self->_high_priority('alert', @_); | |||
| 3428 | 21 | 164 | return $self; | |||
| 3429 | } | |||||
| 3430 | ||||||
| 3431 | sub emergency { | |||||
| 3432 | 23 | 2269 | my $self = shift; | |||
| 3433 | 23 | 26 | $self->_high_priority('emergency', @_); | |||
| 3434 | 19 | 139 | return $self; | |||
| 3435 | } | |||||
| 3436 | ||||||
| 3437 | # --------------------------------------------------------------------------- | |||||
| 3438 | # DESTROY -- release the syslog connection and SIGHUP handler when freed | |||||
| 3439 | # | |||||
| 3440 | # Purpose: Ensure the syslog socket is closed cleanly on object | |||||
| 3441 | # destruction, avoiding resource leaks under persistent | |||||
| 3442 | # interpreters such as mod_perl. | |||||
| 3443 | # Entry: $self -- the logger object being destroyed. | |||||
| 3444 | # Exit: void | |||||
| 3445 | # Side effects: Sends any held email digest. Puts back the program's | |||||
| 3446 | # SIGHUP handler (_release_sighup) if this was the last | |||||
| 3447 | # logger using the module's. Removes the _syslog_opened flag, and calls | |||||
| 3448 | # Sys::Syslog::closelog() if no other instance still uses it. | |||||
| 3449 | # Notes: Uses fully-qualified Sys::Syslog::closelog() so that | |||||
| 3450 | # Test::Mockingbird can intercept the call in tests. | |||||
| 3451 | # --------------------------------------------------------------------------- | |||||
| 3452 | sub DESTROY { | |||||
| 3453 | 1652 | 134133 | my $self = $_[0]; | |||
| 3454 | ||||||
| 3455 | # Destructors run at unpredictable times, e.g. while an exception is | |||||
| 3456 | # propagating, so don't let closelog() change the error variables | |||||
| 3457 | 1652 | 1244 | local ($@, $!, $?); | |||
| 3458 | ||||||
| 3459 | # Send any messages a sendmail digest is still holding | |||||
| 3460 | 1652 0 | 955 0 | eval { $self->flush() } if($self->{_email_digest}); | |||
| 3461 | ||||||
| 3462 | # Collect async sendmail children that have finished | |||||
| 3463 | 1652 | 791 | _reap_email_children() if(@email_children); | |||
| 3464 | ||||||
| 3465 | # openlog/closelog are process-global, so only close the connection | |||||
| 3466 | # when the last instance using it goes away | |||||
| 3467 | 1652 | 893 | if($self->{_syslog_opened}) { | |||
| 3468 | 26 | 20 | delete $self->{_syslog_opened}; | |||
| 3469 | 26 | 47 | Log::Abstraction::Backend::Syslog->release_connection(); | |||
| 3470 | } | |||||
| 3471 | ||||||
| 3472 | # Give the program its SIGHUP handler back if no other logger needs ours | |||||
| 3473 | 1652 | 7413 | $self->_release_sighup() if($self->{_sighup}); | |||
| 3474 | } | |||||
| 3475 | ||||||
| 3476 - 3943 | =head1 EXAMPLES
=head2 CSV file logging for BI import
The code-reference backend gives you full control over the output format.
The example below writes every message at C<trace> level and above as a
CSV row to a file, producing output that can be loaded directly into a
spreadsheet or BI tool (Tableau, Power BI, Metabase, etc.).
Each row contains: C<timestamp>, C<level>, C<class>, C<file>, C<line>, C<message>.
use Log::Abstraction;
my $csv_file = 'app_events.csv';
# Write the header row once (skip if the file already exists and has data).
unless (-s $csv_file) {
open my $fh, '>', $csv_file or die "Cannot open $csv_file: $!";
print $fh qq{timestamp,level,class,file,line,message\n};
close $fh;
}
# Helper: quote a single CSV field (escapes embedded double-quotes).
my $csv_field = sub {
my $v = defined $_[0] ? $_[0] : '';
$v =~ s/"/""/g;
return qq{"$v"};
};
my $logger = Log::Abstraction->new(
level => 'trace', # capture everything from trace upwards
logger => sub {
my $args = $_[0];
my $timestamp = POSIX::strftime('%Y-%m-%dT%H:%M:%SZ', gmtime);
my $message = join(' ', @{ $args->{message} // [] });
open my $fh, '>>', $csv_file or return;
print $fh join(',',
$csv_field->($timestamp),
$csv_field->($args->{level}),
$csv_field->($args->{class}),
$csv_field->($args->{file}),
$csv_field->($args->{line}),
$csv_field->($message),
), "\n";
close $fh;
},
);
$logger->trace('application started');
$logger->info('user logged in', { user => 'alice' });
$logger->warn({ warning => 'disk usage above 80%' });
The resulting C<app_events.csv> looks like:
timestamp,level,class,file,line,message
"2026-05-27T14:00:00Z","trace","Log::Abstraction","app.pl","42","application started"
"2026-05-27T14:00:01Z","info","Log::Abstraction","app.pl","43","user logged in"
"2026-05-27T14:00:02Z","warn","Log::Abstraction","Log/Abstraction.pm","820","disk usage above 80%"
Note: C<class> is always C<Log::Abstraction> (or the subclass name if you subclass the
module). For C<trace>, C<debug>, C<info>, and C<notice> calls, C<file> and C<line>
resolve to the caller's source location. For C<warn> and C<error> calls the
extra C<_high_priority> stack frame shifts the resolution one level inward, so
C<file> and C<line> point into the module rather than the calling script.
For production use, consider replacing the manual C<$csv_field> quoting with
L<Text::CSV> for correct handling of embedded newlines and other edge cases.
If you also want real-time alerting on critical events, add the email logic
directly inside the code-ref callback -- test C<$args-E<gt>{level}> and call
your mailer for C<warn> / C<error> messages while still writing the CSV row
for every message.
Alternatively, use the C<sendmail> hash-ref backend on its own (without the
code-ref) and add a C<level> key to restrict emails to warn-and-above:
my $logger = Log::Abstraction->new(
level => 'warn',
logger => {
sendmail => {
host => 'smtp.example.com',
to => 'ops@example.com',
from => 'logger@example.com',
subject => 'Application alert',
level => 'warn', # only email at warn level and above
min_interval => 300, # at most one alert email per 5 minutes
},
},
);
Note: the C<sendmail> backend writes the module's standard text format, not
CSV. To produce CSV rows I<and> send email alerts from the same logger,
embed both the CSV-write and the mail-send logic inside a single code-ref
callback as described above.
=head1 LIMITATIONS
=over 4
=item B<trace is the same threshold as debug>
syslog has no priority below debug, so C<trace> and C<debug> share one
threshold: a logger at C<debug> level also emits C<trace> messages, and
C<trace> can't be filtered separately.
=item B<Unbounded message history by default>
Every logged message is kept in the history returned by L</messages>. In a
long-running process (a daemon, or under mod_perl) set C<max_messages> to
stop it growing without bound.
=item B<syslog connection is shared>
C<openlog()> and C<closelog()> act on the whole process, so every instance
logging to syslog shares one connection, opened with the C<script_name> of
the first. It is closed when the last such instance is destroyed.
=item B<Structured fields are text in most backends>
Only the history, array, CODE-ref, JSON, journald and Log::Any backends
keep L</Structured fields> as data. Text formats, syslog, email,
Log::Dispatch and object loggers get them as C<key=value> text appended to
the message, and a custom C<format> has no token for them on their own.
=item B<Process-wide state, and no thread safety>
Some state belongs to the whole process, not to a logger: the syslog
connection (above), the C<$SIG{HUP}> handler (see L</logrotate>), and the
list of C<async> email children still to be reaped. The per-logger state
(open log files, the C<min_interval> throttle and C<digest>, the
first-open syslog flag) is stored on the object without locking. Under
Perl ithreads or other concurrency models, objects shared between threads
are not safe.
=item B<Asynchronous email uses fork>
The C<sendmail> C<async> option sends each email from a child made with
C<fork>. That may not suit every program: under mod_perl the child is a
copy of the Apache process; with ithreads only the calling thread is
copied; and in an event loop (L<AnyEvent>, L<IO::Async>, L<Mojo::IOLoop>)
the child is reaped by this module, not by the loop's child watcher. A
program that reaps every child itself (e.g. C<waitpid(-1, ...)> in a
C<$SIG{CHLD}> handler) sees these children too. The child's success or
failure isn't reported back: a failure is carped by the child and the
message is lost. Without C<async> the email is sent in the log call.
=item B<OpenTelemetry not yet supported>
The OTel Logs SDK for Perl is incomplete; see the TODO block at the top of
F<lib/Log/Abstraction.pm> for a full status report and the list of blockers.
Monitor L<https://metacpan.org/pod/OpenTelemetry::SDK> for progress.
=item B<Log::Log4perl is a de-facto required dependency>
When no C<logger>, C<file>, C<fd> or C<array> backend is configured, C<new()>
loads L<Log::Log4perl> and uses it as the default backend, so it is a
required dependency even for applications that never use it.
=back
=head1 AUTHOR
Nigel Horne C<njh@nigelhorne.com>
=head1 SEE ALSO
=over 4
=item * L<Log::Any> and L<Log::Any::Adapter::Abstraction>
Route messages from any C<Log::Any>-using CPAN module through
C<Log::Abstraction> with a single C<Log::Any::Adapter-E<gt>set()> call,
or send messages on to Log::Any with the C<log_any> backend.
=item * L<Log::Abstraction::Backend>
The classes that send messages to each kind of backend.
=item * L<Log::Dispatch>
Send messages on to a C<Log::Dispatch> object with the C<log_dispatch>
backend (see L</Forwarding to Log::Any and Log::Dispatch>).
=item * L<Test Dashboard|https://nigelhorne.github.io/Log-Abstraction/coverage/>
=back
=head1 SUPPORT
This module is provided as-is without any warranty.
Please report any bugs or feature requests to C<bug-log-abstraction at rt.cpan.org>,
or through the web interface at
L<http://rt.cpan.org/NoAuth/ReportBug.html?Queue=Log-Abstraction>.
I will be notified, and then you'll
automatically be notified of progress on your bug as I make changes.
You can find documentation for this module with the perldoc command.
perldoc Log::Abstraction
You can also look for information at:
=over 4
=item * MetaCPAN
L<https://metacpan.org/dist/Log-Abstraction>
=item * RT: CPAN's request tracker
L<https://rt.cpan.org/NoAuth/Bugs.html?Dist=Log-Abstraction>
=item * CPAN Testers' Matrix
L<http://matrix.cpantesters.org/?dist=Log-Abstraction>
=item * CPAN Testers Dependencies
L<http://deps.cpantesters.org/?module=Log::Abstraction>
=back
=encoding utf-8
=head1 FORMAL SPECIFICATION
=head2 new
FIELDS == STRING ⸠VALUE structured fields (see Structured fields)
ENTRY == { level : STRING; message : STRING; fields : FIELDS }
entry(l, m, f) == {level ⦠l, message ⦠Ï(m)} ⪠(if f = â
then â
else {fields ⦠Ï(f)})
Ï(x) == if redact = â
then x
else x with each match of redact replaced by '[REDACTED]'
(in strings, recursively in plain hashes and arrays)
ââ LogState ââââââââââââââââââââââââââââââââââââââââââââââââââ
â level : â¤
â messages : seq ENTRY
â max_messages : â ⪠{â}
â logger : LOGGER
â redact : REGEX ⪠{â
}
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â 0 ⤠level ⤠7
â #messages ⤠max_messages
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
ââ New âââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â args? : Args
â result! : LogState
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â result!.level = syslog_values(args?.level ⨠'warning')
â result!.messages = â¨â©
â result!.max_messages = args?.max_messages ⨠â
â result!.redact = â args?.redact {one regex matching any; â
if none}
â args?.redact â â
⹠¬('' â L(result!.redact))
â args?.logger â â
â¹ result!.logger = args?.logger
â args?.logger = â
â§ args?.file = â
â§ args?.fd = â
â§ args?.array = â
â â¹ result!.logger = Log4perl
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
Clone operation (called on an existing object):
ââ Clone âââââââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â overrides? : Args
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â result!.level = syslog_values(overrides?.level ⨠level)
â result!.messages = messages {new sequence; entries shared}
â result!.logger = overrides?.logger ⨠logger
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
=head2 level
ââ LevelGet âââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â result! : â¤
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â result! = level
â 0 ⤠result! â§ result! ⤠7
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
ââ LevelSet âââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â new_level? : STRING
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â new_level? â dom(syslog_values)
â level' = syslog_values(new_level?)
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
ââ LevelSetInvalid ââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â new_level? : STRING
â result! : undef
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â new_level? â ''
â new_level? â dom(syslog_values)
â carp("invalid syslog level")
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
level(new_level?) ⡠LevelSet ⨠LevelSetInvalid
=head2 is_trace, is_debug, is_info, is_notice, is_warn, is_error, is_critical, is_alert, is_emergency
ââ IsLevel ââââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â lvl? : LEVEL
â result! : BOOLEAN
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â result! = (level ⥠syslog_values(lvl?))
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
is_<lvl> â¡ IsLevel[lvl? := lvl]
=head2 messages
ââ Messages âââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â result! : seq ENTRY
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â result! = messages
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
=head2 flush
ââ Flush ââââââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â result! : LogState
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â digest â â¨â© â§ (sent(digest) ⨠async â§ forked) â¹
â digest' = â¨â© â§ last_email_sent' = now
â digest â â¨â© ⧠¬sent(digest) ⧠¬(async â§ forked) â¹ digest' = digest
â digest = â¨â© â¹ digest' = digest
â messages' = messages
â result! = self
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
=head2 reopen
INTERVAL == ⤠reopen_interval: seconds, 0 or -1
HANDLE == { fh; dev; ino; sighup : â; opened : â }
ââ OpenFiles âââââââââââââââââââââââââââââââââââââââââââââââââ
â handles : PATH ⸠HANDLE
â reopen_interval : INTERVAL
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â reopen_interval ⥠-1
â reopen_interval = 0 â¹ handles = â
(between log calls)
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
A handle h on path p is used for the next write iff
stat(p) = (h.dev, h.ino) â§ h.sighup = sighup_count
⧠(reopen_interval = -1 ⨠now - h.opened < reopen_interval)
and is otherwise closed and p opened again.
ââ Reopen ââââââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎOpenFiles
â result! : LogState
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â handles' = â
â reopen_interval' = reopen_interval
â result! = self
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
=head2 trace
ââ Trace ââââââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â msg? : seq STRING
â fields? : FIELDS
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â syslog_values('trace') ⤠level
â messages' = messages ⢠â¨entry('trace', â(msg?), fields?)â©
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
=head2 debug
ââ Debug ââââââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â msg? : seq STRING
â fields? : FIELDS
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â syslog_values('debug') ⤠level
â messages' = messages ⢠â¨entry('debug', â(msg?), fields?)â©
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
=head2 info
ââ Info âââââââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â msg? : seq STRING
â fields? : FIELDS
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â syslog_values('info') ⤠level
â messages' = messages ⢠â¨entry('info', â(msg?), fields?)â©
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
=head2 notice
ââ Notice âââââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â msg? : seq STRING
â fields? : FIELDS
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â syslog_values('notice') ⤠level
â messages' = messages ⢠â¨entry('notice', â(msg?), fields?)â©
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
=head2 warn
ââ Warn âââââââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â msg? : seq STRING | { warning : STRING | seq STRING }
â fields? : FIELDS
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â msg? â â
â§ join(msg?) â ''
â syslog_values('warn') ⤠level
â messages' = messages ⢠â¨entry('warn', join(msg?), fields?)â©
â (carp_on_warn ⨠no_backend) â¹ carp(join(msg?))
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
no_backend â¡ logger = â
â§ array = â
â§ file = â
â§ fd = â
Called as a class method (no LogState): carp(join(msg?)), and
messages is not touched.
=head2 error
ââ Error ââââââââââââââââââââââââââââââââââââââââââââââââââââ
â ÎLogState
â msg? : seq STRING | { warning : STRING | seq STRING }
â fields? : FIELDS
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
â msg? â â
â§ join(msg?) â ''
â syslog_values('error') ⤠level
â messages' = messages ⢠â¨entry('error', join(msg?), fields?)â©
â (croak_on_error ⨠no_backend) â¹ execution_continues = false
ââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââââ
Called as a class method (no LogState): croak(join(msg?)).
=head2 fatal
fatal â¡ error (identical operation schema)
=head2 critical, alert, emergency
The Error schema, with 'error' replaced by 'critical', 'alert' or
'emergency' respectively.
In every logging schema, when #messages' would exceed max_messages
the oldest entries are dropped: messages' = the last max_messages
entries. fields? is a hashref given after the message (see
Structured fields); fields? = â
when there is none.
=head1 COPYRIGHT AND LICENSE
Copyright (C) 2025-2026 Nigel Horne
Usage is subject to the GPL2 licence terms.
If you use it,
please let me know.
=cut | |||||
| 3944 | ||||||
| 3945 | 1; | |||||