From 59d96420c80497a9ff296d438c36cbe4883ca8ef Mon Sep 17 00:00:00 2001 From: Hans van Kranenburg Date: Fri, 22 Apr 2016 23:11:00 +0200 Subject: [PATCH 1/5] btrbk: add transaction logging to syslog Add configuration option transaction_syslog, which can be set to a short name of a syslog facility, like user or local5. Most of the ones besides localX do not really make sense, but whatever, let the user decide. The only logging that is relevant for logging to syslog is the logging generated inside sub action, so it's easy to hijack all messages in there and also send them to syslog if needed. All output is done via print_formatted, which expects a file handle. So, abuse a file handle to a string to be able to change as less code as needed for this feature. Since syslog already adds the timestamps for us, I added a syslog formatting pattern, which is very similar to tlog, omitting the timestap. --- ChangeLog | 1 + btrbk | 39 ++++++++++++++++++++++++++++++++++----- doc/btrbk.conf.5 | 9 +++++++++ 3 files changed, 44 insertions(+), 5 deletions(-) diff --git a/ChangeLog b/ChangeLog index ddfce4d..75d7fd1 100644 --- a/ChangeLog +++ b/ChangeLog @@ -2,6 +2,7 @@ btrbk-current * Bugfix: set correct parent section when propagating targets (close: #85). + * Add syslog output for transaction log. btrbk-0.23.0 diff --git a/btrbk b/btrbk index fe93c3b..c1b7c2e 100755 --- a/btrbk +++ b/btrbk @@ -45,6 +45,8 @@ use warnings FATAL => qw( all ); use Carp qw(confess); use Getopt::Long qw(GetOptions); use Time::Local qw( timelocal timegm timegm_nocheck ); +use Sys::Syslog; +use Sys::Syslog qw(:standard :macros); our $VERSION = "0.23.1-dev"; our $AUTHOR = 'Axel Burri '; @@ -69,6 +71,11 @@ my $ssh_cipher_match = qr/[a-z0-9][a-z0-9@.-]+/; my $safe_cmd_match = qr/[0-9a-zA-Z_@=\+\-\.\/]+/; # $file_match plus '=': good enough for our purpose my %day_of_week_map = ( sunday => 0, monday => 1, tuesday => 2, wednesday => 3, thursday => 4, friday => 5, saturday => 6 ); +my %syslog_facility_map = ( + user => LOG_USER, mail => LOG_MAIL, daemon => LOG_DAEMON, auth => LOG_AUTH, lpr => LOG_LPR, news => LOG_NEWS, + cron => LOG_CRON, authpriv => LOG_AUTHPRIV, local0 => LOG_LOCAL0, local1 => LOG_LOCAL1, local2 => LOG_LOCAL2, + local3 => LOG_LOCAL3, local4 => LOG_LOCAL4, local5 => LOG_LOCAL5, local6 => LOG_LOCAL6, local7 => LOG_LOCAL7, +); my %config_options = ( # NOTE: the parser always maps "no" to undef @@ -94,6 +101,7 @@ my %config_options = ( ssh_cipher_spec => { default => "default", accept_regexp => qr/^$ssh_cipher_match(,$ssh_cipher_match)*$/ }, rate_limit => { default => undef, accept => [ "no" ], accept_regexp => qr/^[0-9]+[kmgt]?$/, require_bin => '/usr/bin/pv' }, transaction_log => { default => undef, accept_file => { absolute => 1 } }, + transaction_syslog => { default => undef, accept => [ keys %syslog_facility_map ] }, raw_target_compress => { default => undef, accept => [ "no", "gzip", "bzip2", "xz" ] }, raw_target_compress_level => { default => "default", accept => [ "default" ], accept_numeric => 1 }, @@ -178,6 +186,7 @@ my %table_formats = ( long => [ qw( localtime type status duration target_host target_subvol source_host source_subvol parent_subvol message ) ], raw => [ qw( time localtime type status duration target_url source_url parent_url message ) ], tlog => [ qw( localtime type status duration target_url source_url parent_url message ) ], + syslog => [ qw( type status duration target_url source_url parent_url message ) ], }, origin_tree => { table => [ qw( tree uuid parent_uuid received_uuid ) ], @@ -202,6 +211,7 @@ my $err = ""; my $abrt = ""; # last ABORTED() message my $output_format; my $tlog_fh; +my $syslog_facility; my $current_transaction; my @transaction_log; my %config_override; @@ -319,7 +329,7 @@ sub ABORTED($;$) } -sub init_transaction_log($) +sub init_transaction_log($$) { my $file = shift; if(defined($file) && (not $dryrun)) { @@ -332,6 +342,11 @@ sub init_transaction_log($) ERROR "Failed to open transaction log '$file': $!"; } } + my $config_syslog_facility = shift; + if(defined($config_syslog_facility) && (not $dryrun)) { + $syslog_facility = $syslog_facility_map{$config_syslog_facility}; + openlog("btrbk", 0, $syslog_facility); + } action("startup", status => "v$VERSION", message => "$VERSION_INFO"); } @@ -341,6 +356,7 @@ sub close_transaction_log() DEBUG "Closing transaction log"; close $tlog_fh || ERROR "Failed to close transaction log: $!"; } + closelog if defined $syslog_facility; } sub action($@) @@ -352,6 +368,16 @@ sub action($@) $h->{time} = $time; $h->{localtime} = timestamp($time, 'debug-iso'); print_formatted("transaction", [ $h ], output_format => "tlog", no_header => 1, outfile => $tlog_fh) if($tlog_fh); + if (defined($syslog_facility)) { + my $msg = q{}; + open my $msg_fh, '+<', \$msg; + print_formatted("transaction", [ $h ], output_format => "syslog", no_header => 1, outfile => $msg_fh); + seek($msg_fh, 0, 0); + while (my $line = <$msg_fh>) { + syslog(LOG_INFO, $line); + } + close $msg_fh; + } push @transaction_log, $h; return $h; } @@ -3162,7 +3188,7 @@ sub print_formatted(@) print $fh join(' ', map { "$_=\"" . ($row->{$_} // "") . "\""; } @$keys) . "\n"; } } - elsif($format eq "tlog") + elsif($format eq "tlog" || $format eq "syslog") { # output: value0 value1, ... unless($args{no_header}) { @@ -3619,7 +3645,8 @@ MAIN: # thing used from the configuration is the SSH and transaction log # stuff. # - init_transaction_log(config_key($config, "transaction_log")); + init_transaction_log(config_key($config, "transaction_log"), + config_key($config, "transaction_syslog")); my $src_url = $filter_args[0] || die; my $archive_url = $filter_args[1] || die; @@ -4518,7 +4545,8 @@ MAIN: # # identify and delete incomplete backups # - init_transaction_log(config_key($config, "transaction_log")); + init_transaction_log(config_key($config, "transaction_log"), + config_key($config, "transaction_syslog")); my @out; foreach my $sroot (vinfo_subsection($config, 'volume')) { @@ -4615,7 +4643,8 @@ MAIN: if($action_run) { - init_transaction_log(config_key($config, "transaction_log")); + init_transaction_log(config_key($config, "transaction_log"), + config_key($config, "transaction_syslog")); if($resume_only) { INFO "Skipping snapshot creation (option \"-r\" present)"; diff --git a/doc/btrbk.conf.5 b/doc/btrbk.conf.5 index 7a7ccfc..8b51b89 100644 --- a/doc/btrbk.conf.5 +++ b/doc/btrbk.conf.5 @@ -75,6 +75,15 @@ subvolume delete) as well as abort messages are logged to , in a space-separated table format. .RE .PP +\fBtransaction_syslog\fR +.RS 4 +If set, all transactions (snapshot create, subvolume send-receive, +subvolume delete) as well as abort messages are logged to syslog, in a +space-separated format. The facility parameter accepts a short +lowercase syslog facility name, like \[lq]daemon\[rq] or \[lq]local7\[rq]. +The program name used in the messages is "btrbk". +.RE +.PP \fBtimestamp_format\fR short|long|long-iso .RS 4 Timestamp format used as postfix for new snapshot subvolume From c424d917b6fddb3e40810a2731f7697a0fa95125 Mon Sep 17 00:00:00 2001 From: Axel Burri Date: Mon, 25 Apr 2016 18:36:15 +0200 Subject: [PATCH 2/5] btrbk: syslog: only load Sys::Syslog module if configuration option is set; soft-fail on syslog calls --- btrbk | 34 +++++++++++++++++++++------------- 1 file changed, 21 insertions(+), 13 deletions(-) diff --git a/btrbk b/btrbk index c1b7c2e..197846f 100755 --- a/btrbk +++ b/btrbk @@ -45,8 +45,6 @@ use warnings FATAL => qw( all ); use Carp qw(confess); use Getopt::Long qw(GetOptions); use Time::Local qw( timelocal timegm timegm_nocheck ); -use Sys::Syslog; -use Sys::Syslog qw(:standard :macros); our $VERSION = "0.23.1-dev"; our $AUTHOR = 'Axel Burri '; @@ -71,11 +69,7 @@ my $ssh_cipher_match = qr/[a-z0-9][a-z0-9@.-]+/; my $safe_cmd_match = qr/[0-9a-zA-Z_@=\+\-\.\/]+/; # $file_match plus '=': good enough for our purpose my %day_of_week_map = ( sunday => 0, monday => 1, tuesday => 2, wednesday => 3, thursday => 4, friday => 5, saturday => 6 ); -my %syslog_facility_map = ( - user => LOG_USER, mail => LOG_MAIL, daemon => LOG_DAEMON, auth => LOG_AUTH, lpr => LOG_LPR, news => LOG_NEWS, - cron => LOG_CRON, authpriv => LOG_AUTHPRIV, local0 => LOG_LOCAL0, local1 => LOG_LOCAL1, local2 => LOG_LOCAL2, - local3 => LOG_LOCAL3, local4 => LOG_LOCAL4, local5 => LOG_LOCAL5, local6 => LOG_LOCAL6, local7 => LOG_LOCAL7, -); +my @syslog_facilities = qw( user mail daemon auth lpr news cron authpriv local0 local1 local2 local3 local4 local5 local6 local7 ); my %config_options = ( # NOTE: the parser always maps "no" to undef @@ -101,7 +95,7 @@ my %config_options = ( ssh_cipher_spec => { default => "default", accept_regexp => qr/^$ssh_cipher_match(,$ssh_cipher_match)*$/ }, rate_limit => { default => undef, accept => [ "no" ], accept_regexp => qr/^[0-9]+[kmgt]?$/, require_bin => '/usr/bin/pv' }, transaction_log => { default => undef, accept_file => { absolute => 1 } }, - transaction_syslog => { default => undef, accept => [ keys %syslog_facility_map ] }, + transaction_syslog => { default => undef, accept => \@syslog_facilities }, raw_target_compress => { default => undef, accept => [ "no", "gzip", "bzip2", "xz" ] }, raw_target_compress_level => { default => "default", accept => [ "default" ], accept_numeric => 1 }, @@ -332,6 +326,7 @@ sub ABORTED($;$) sub init_transaction_log($$) { my $file = shift; + my $config_syslog_facility = shift; if(defined($file) && (not $dryrun)) { if(open($tlog_fh, ">> $file")) { # print headers @@ -342,10 +337,16 @@ sub init_transaction_log($$) ERROR "Failed to open transaction log '$file': $!"; } } - my $config_syslog_facility = shift; if(defined($config_syslog_facility) && (not $dryrun)) { - $syslog_facility = $syslog_facility_map{$config_syslog_facility}; - openlog("btrbk", 0, $syslog_facility); + eval { local $SIG{'__DIE__'}; + require Sys::Syslog; + }; + if($@) { + WARN "Syslog disabled: $@"; + } else { + $syslog_facility = $config_syslog_facility; + Sys::Syslog::openlog("btrbk", "", $syslog_facility); + } } action("startup", status => "v$VERSION", message => "$VERSION_INFO"); } @@ -356,7 +357,11 @@ sub close_transaction_log() DEBUG "Closing transaction log"; close $tlog_fh || ERROR "Failed to close transaction log: $!"; } - closelog if defined $syslog_facility; + if(defined($syslog_facility)) { + eval { local $SIG{'__DIE__'}; + Sys::Syslog::closelog(); + }; + } } sub action($@) @@ -374,7 +379,10 @@ sub action($@) print_formatted("transaction", [ $h ], output_format => "syslog", no_header => 1, outfile => $msg_fh); seek($msg_fh, 0, 0); while (my $line = <$msg_fh>) { - syslog(LOG_INFO, $line); + eval { local $SIG{'__DIE__'}; + Sys::Syslog::syslog("info", $line); + }; + if($@) { WARN "syslog failed: $@"; } } close $msg_fh; } From 47eb14f5fbf91862bb6072221605b02a7b7d574f Mon Sep 17 00:00:00 2001 From: Axel Burri Date: Mon, 25 Apr 2016 19:40:11 +0200 Subject: [PATCH 3/5] btrbk: syslog: add syslog hack in print_formatted(); remove print-to-scalar hack --- btrbk | 49 +++++++++++++++++++++++++++---------------------- 1 file changed, 27 insertions(+), 22 deletions(-) diff --git a/btrbk b/btrbk index 197846f..94f97b0 100755 --- a/btrbk +++ b/btrbk @@ -205,7 +205,7 @@ my $err = ""; my $abrt = ""; # last ABORTED() message my $output_format; my $tlog_fh; -my $syslog_facility; +my $syslog_enabled = 0; my $current_transaction; my @transaction_log; my %config_override; @@ -338,14 +338,15 @@ sub init_transaction_log($$) } } if(defined($config_syslog_facility) && (not $dryrun)) { - eval { local $SIG{'__DIE__'}; - require Sys::Syslog; - }; + eval { + local $SIG{'__DIE__'}; + require Sys::Syslog; + }; if($@) { WARN "Syslog disabled: $@"; } else { - $syslog_facility = $config_syslog_facility; - Sys::Syslog::openlog("btrbk", "", $syslog_facility); + $syslog_enabled = 1; + Sys::Syslog::openlog("btrbk", "", $config_syslog_facility); } } action("startup", status => "v$VERSION", message => "$VERSION_INFO"); @@ -357,7 +358,7 @@ sub close_transaction_log() DEBUG "Closing transaction log"; close $tlog_fh || ERROR "Failed to close transaction log: $!"; } - if(defined($syslog_facility)) { + if($syslog_enabled) { eval { local $SIG{'__DIE__'}; Sys::Syslog::closelog(); }; @@ -373,19 +374,7 @@ sub action($@) $h->{time} = $time; $h->{localtime} = timestamp($time, 'debug-iso'); print_formatted("transaction", [ $h ], output_format => "tlog", no_header => 1, outfile => $tlog_fh) if($tlog_fh); - if (defined($syslog_facility)) { - my $msg = q{}; - open my $msg_fh, '+<', \$msg; - print_formatted("transaction", [ $h ], output_format => "syslog", no_header => 1, outfile => $msg_fh); - seek($msg_fh, 0, 0); - while (my $line = <$msg_fh>) { - eval { local $SIG{'__DIE__'}; - Sys::Syslog::syslog("info", $line); - }; - if($@) { WARN "syslog failed: $@"; } - } - close $msg_fh; - } + print_formatted("transaction", [ $h ], output_format => "syslog", no_header => 1) if($syslog_enabled); # dirty hack, this calls syslog() push @transaction_log, $h; return $h; } @@ -415,6 +404,17 @@ sub end_transaction($$) $current_transaction = undef; } +sub syslog($) +{ + my $line = shift; + return undef unless($syslog_enabled); + eval { + local $SIG{'__DIE__'}; + Sys::Syslog::syslog("info", $line); + }; + if($@) { WARN "syslog failed: $@"; } +} + sub safe_cmd($) { my $aref = shift; @@ -3196,14 +3196,19 @@ sub print_formatted(@) print $fh join(' ', map { "$_=\"" . ($row->{$_} // "") . "\""; } @$keys) . "\n"; } } - elsif($format eq "tlog" || $format eq "syslog") + elsif(($format eq "tlog") || ($format eq "syslog")) { # output: value0 value1, ... unless($args{no_header}) { print $fh join(' ', @$keys) . "\n"; } foreach my $row (@$data) { - print $fh join(' ', map { ((defined($row->{$_}) && ($_ eq "message")) ? '# ' : '') . ($row->{$_} // "-") } @$keys) . "\n"; + my $line = join(' ', map { ((defined($row->{$_}) && ($_ eq "message")) ? '# ' : '') . ($row->{$_} // "-") } @$keys); + if($format eq "syslog") { # dirty hack, ignore outfile on syslog format + syslog($line); + } else { + print $fh ($line . "\n"); + } } } else From 7e7c28f8f18453549b90d7721ac1dace586f7aed Mon Sep 17 00:00:00 2001 From: Axel Burri Date: Mon, 25 Apr 2016 21:05:46 +0200 Subject: [PATCH 4/5] btrbk: add eval_quiet(), a simple wrapper around eval, disabling $SIG_(__DIE__) --- btrbk | 46 +++++++++++++++++++++------------------------- 1 file changed, 21 insertions(+), 25 deletions(-) diff --git a/btrbk b/btrbk index 94f97b0..bde9a65 100755 --- a/btrbk +++ b/btrbk @@ -322,6 +322,11 @@ sub ABORTED($;$) $config->{ABORTED} = $abrt; } +sub eval_quiet(&) +{ + local $SIG{__DIE__}; + return eval { $_[0]->() } +} sub init_transaction_log($$) { @@ -338,15 +343,14 @@ sub init_transaction_log($$) } } if(defined($config_syslog_facility) && (not $dryrun)) { - eval { - local $SIG{'__DIE__'}; - require Sys::Syslog; - }; - if($@) { - WARN "Syslog disabled: $@"; - } else { + DEBUG "Opening syslog"; + if(eval_quiet { require Sys::Syslog; }) { $syslog_enabled = 1; Sys::Syslog::openlog("btrbk", "", $config_syslog_facility); + DEBUG "Syslog enabled"; + } + else { + WARN "Syslog disabled: $@"; } } action("startup", status => "v$VERSION", message => "$VERSION_INFO"); @@ -359,9 +363,8 @@ sub close_transaction_log() close $tlog_fh || ERROR "Failed to close transaction log: $!"; } if($syslog_enabled) { - eval { local $SIG{'__DIE__'}; - Sys::Syslog::closelog(); - }; + DEBUG "Closing syslog"; + eval_quiet { Sys::Syslog::closelog(); }; } } @@ -406,13 +409,9 @@ sub end_transaction($$) sub syslog($) { - my $line = shift; return undef unless($syslog_enabled); - eval { - local $SIG{'__DIE__'}; - Sys::Syslog::syslog("info", $line); - }; - if($@) { WARN "syslog failed: $@"; } + my $line = shift; + eval_quiet { Sys::Syslog::syslog("info", $line); }; } sub safe_cmd($) @@ -1590,15 +1589,12 @@ sub add_btrbk_filename_info($;$) my $zz = $+{zz}; my $time; - eval { - local $SIG{'__DIE__'}; - if(defined($zz)) { - $time = timegm(@tm); - } else { - $time = timelocal(@tm); - } - }; - if($@) { + if(defined($zz)) { + eval_quiet { $time = timegm(@tm); }; + } else { + eval_quiet { $time = timelocal(@tm); }; + } + unless(defined($time)) { WARN "Illegal timestamp on subvolume \"$node->{REL_PATH}\", ignoring"; # WARN "$@"; # sadly Time::Local croaks, which also prints the line number from here. return undef; From 7a469597acad756aec79d23a9096d8892b889712 Mon Sep 17 00:00:00 2001 From: Axel Burri Date: Thu, 28 Apr 2016 12:44:33 +0200 Subject: [PATCH 5/5] documentation: describe transaction log table format; cosmetics --- ChangeLog | 2 +- doc/btrbk.conf.5 | 14 +++++++------- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/ChangeLog b/ChangeLog index 75d7fd1..a35d259 100644 --- a/ChangeLog +++ b/ChangeLog @@ -2,7 +2,7 @@ btrbk-current * Bugfix: set correct parent section when propagating targets (close: #85). - * Add syslog output for transaction log. + * Add syslog output of transaction log (close #82). btrbk-0.23.0 diff --git a/doc/btrbk.conf.5 b/doc/btrbk.conf.5 index 8b51b89..24ae938 100644 --- a/doc/btrbk.conf.5 +++ b/doc/btrbk.conf.5 @@ -1,4 +1,4 @@ -.TH "btrbk.conf" "5" "2016-04-25" "btrbk v0.23.1-dev" "" +.TH "btrbk.conf" "5" "2016-04-28" "btrbk v0.23.1-dev" "" .\" disable hyphenation .nh .\" disable justification (adjust text to left margin only) @@ -72,16 +72,16 @@ allowed. .RS 4 If set, all transactions (snapshot create, subvolume send-receive, subvolume delete) as well as abort messages are logged to , in a -space-separated table format. +space-separated table format: "localtime type status duration +target_url source_url parent_url message". .RE .PP \fBtransaction_syslog\fR .RS 4 -If set, all transactions (snapshot create, subvolume send-receive, -subvolume delete) as well as abort messages are logged to syslog, in a -space-separated format. The facility parameter accepts a short -lowercase syslog facility name, like \[lq]daemon\[rq] or \[lq]local7\[rq]. -The program name used in the messages is "btrbk". +If set, all transactions (as described in \fItransaction_log\fR above) +are logged to syslog. The facility parameter accepts a lowercase +syslog facility name, like \[lq]daemon\[rq] or \[lq]local7\[rq]. The +program name used in the messages is "btrbk". .RE .PP \fBtimestamp_format\fR short|long|long-iso