From f9dafa35a12889067909c1fa9337ec33319969b1 Mon Sep 17 00:00:00 2001 From: Richard Hansen Date: Wed, 22 May 2024 18:15:01 -0400 Subject: [PATCH 1/6] Rename `$msgs` to `$emailbody` to improve readability --- ddclient.in | 26 ++++++++++++++------------ 1 file changed, 14 insertions(+), 12 deletions(-) diff --git a/ddclient.in b/ddclient.in index 84f7863..03f3e39 100755 --- a/ddclient.in +++ b/ddclient.in @@ -125,8 +125,8 @@ if ($program =~ /test/i) { $savedir = 'URL'; } -my $msgs = ''; -my $last_msgs = ''; +my $emailbody = ''; +my $last_emailbody = ''; ## If run as *d (e.g., ddclientd) then daemonize by default (but allow ## flags and options to override). @@ -2311,19 +2311,19 @@ sub sendmail { if (opt('mail-failure') && ($result ne 'OK' && $result ne '0')) { $recipients = opt('mail-failure'); } - if ($msgs && $recipients && $msgs ne $last_msgs) { + if ($emailbody && $recipients && $emailbody ne $last_emailbody) { pipecmd("sendmail -oi $recipients", "To: $recipients", "Subject: status report from $program\@$hostname", "\r\n", - $msgs, + $emailbody, "", "regards,", " $program\@$hostname (version $version)" ); } - $last_msgs = $msgs; - $msgs = ''; + $last_emailbody = $emailbody; + $emailbody = ''; } ###################################################################### ## split_by_comma @@ -2390,7 +2390,7 @@ sub ynu { my $_in_msg = 0; sub _msg { my $fh = shift; - my $log = shift; + my $email = shift; my $prefix = shift; my $format = shift; my $buffer = sprintf $format, @_; @@ -2409,11 +2409,13 @@ sub _msg { $buffer .= "\n"; print $fh $buffer; - $msgs .= $buffer if $log; - if ($log && !$_in_msg) { - ++$_in_msg; # avoid infinite recursion if logger calls _msg - logger($buffer); - --$_in_msg; + if ($email) { + $emailbody .= $buffer; + if (!$_in_msg) { + ++$_in_msg; # avoid infinite recursion if logger calls _msg + logger($buffer); + --$_in_msg; + } } } From 065b22771164ec0abdbce2b4ca5f3bf87dea3c5e Mon Sep 17 00:00:00 2001 From: Richard Hansen Date: Wed, 22 May 2024 01:54:31 -0400 Subject: [PATCH 2/6] logmsg: New low-level logging interface --- Makefile.am | 1 + ddclient.in | 55 ++++++++++++------------ t/logmsg.pl | 121 ++++++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 150 insertions(+), 27 deletions(-) create mode 100644 t/logmsg.pl diff --git a/Makefile.am b/Makefile.am index 6412ede..9503c04 100644 --- a/Makefile.am +++ b/Makefile.am @@ -68,6 +68,7 @@ handwritten_tests = \ t/is-and-extract-ipv4.pl \ t/is-and-extract-ipv6.pl \ t/is-and-extract-ipv6-global.pl \ + t/logmsg.pl \ t/parse_assignments.pl \ t/skip.pl \ t/ssl-validate.pl \ diff --git a/ddclient.in b/ddclient.in index 03f3e39..9672440 100755 --- a/ddclient.in +++ b/ddclient.in @@ -125,7 +125,7 @@ if ($program =~ /test/i) { $savedir = 'URL'; } -my $emailbody = ''; +our $emailbody = ''; my $last_emailbody = ''; ## If run as *d (e.g., ddclientd) then daemonize by default (but allow @@ -2382,20 +2382,22 @@ sub ynu { return $undef; } ###################################################################### -## msg -## debug -## warning -## fatal +## Logging ###################################################################### -my $_in_msg = 0; -sub _msg { - my $fh = shift; - my $email = shift; - my $prefix = shift; - my $format = shift; - my $buffer = sprintf $format, @_; +my $_in_logmsg = 0; +sub logmsg { + my %args = ( + msg => '', + pfx => '', + fh => *STDERR, + email => 0, # If truthy, the message is also included in the next email. + (@_ % 2) ? (msg => pop) : (), + @_, + ); + my $buffer = $args{msg}; chomp($buffer); + my $prefix = $args{pfx}; $prefix = sprintf "%-9s ", $prefix if $prefix; if ($file) { $prefix .= "file $file"; @@ -2407,27 +2409,26 @@ sub _msg { $buffer =~ s/\n/\n$prefix/g; } $buffer .= "\n"; - print $fh $buffer; + print({$args{fh}} $buffer); - if ($email) { + if ($args{email}) { $emailbody .= $buffer; - if (!$_in_msg) { - ++$_in_msg; # avoid infinite recursion if logger calls _msg + if (!$_in_logmsg) { + ++$_in_logmsg; # avoid infinite recursion if logger calls logmsg logger($buffer); - --$_in_msg; + --$_in_logmsg; } } - } -sub msg { _msg(*STDOUT, 0, '', @_); } -sub verbose { _msg(*STDOUT, 1, @_) if opt('verbose'); } -sub info { _msg(*STDOUT, 1, 'INFO:', @_) if opt('verbose'); } -sub debug { _msg(*STDOUT, 0, 'DEBUG:', @_) if opt('debug'); } -sub debug2 { _msg(*STDOUT, 0, 'DEBUG:', @_) if opt('debug') && opt('verbose'); } -sub warning { _msg(*STDERR, 1, 'WARNING:', @_); } -sub fatal { _msg(*STDERR, 1, 'FATAL:', @_); sendmail(); exit(1); } -sub success { _msg(*STDOUT, 1, 'SUCCESS:', @_); } -sub failed { _msg(*STDERR, 1, 'FAILED:', @_); $result = 'FAILED'; } +sub msg { logmsg(fh => *STDOUT, sprintf(shift, @_)); } +sub verbose { logmsg(fh => *STDOUT, email => 1, pfx => pop, sprintf(shift, @_)) if opt('verbose'); } +sub info { logmsg(fh => *STDOUT, email => 1, pfx => 'INFO:', sprintf(shift, @_)) if opt('verbose'); } +sub debug { logmsg(fh => *STDOUT, pfx => 'DEBUG:', sprintf(shift, @_)) if opt('debug'); } +sub debug2 { logmsg(fh => *STDOUT, pfx => 'DEBUG:', sprintf(shift, @_)) if opt('debug') && opt('verbose'); } +sub warning { logmsg( email => 1, pfx => 'WARNING:', sprintf(shift, @_)); } +sub fatal { logmsg( email => 1, pfx => 'FATAL:', sprintf(shift, @_)); sendmail(); exit(1); } +sub success { logmsg(fh => *STDOUT, email => 1, pfx => 'SUCCESS:', sprintf(shift, @_)); } +sub failed { logmsg( email => 1, pfx => 'FAILED:', sprintf(shift, @_)); $result = 'FAILED'; } sub prettytime { return scalar(localtime(shift)); } sub prettyinterval { diff --git a/t/logmsg.pl b/t/logmsg.pl new file mode 100644 index 0000000..ccc43d2 --- /dev/null +++ b/t/logmsg.pl @@ -0,0 +1,121 @@ +use Test::More; +SKIP: { eval { require Test::Warnings; } or skip($@, 1); } +eval { require 'ddclient'; } or BAIL_OUT($@); + +{ + my $output; + open(my $fh, '>', \$output); + local *STDERR = $fh; + ddclient::logmsg('to STDERR'); + close($fh); + is($output, "to STDERR\n", 'logs to STDERR by default'); +} + +{ + my $output; + open(my $fh, '>', \$output); + ddclient::logmsg(fh => $fh, 'to file handle'); + close($fh); + is($output, "to file handle\n", 'logs to provided file handle'); +} + +my @test_cases = ( + { + desc => 'adds a newline', + args => ['xyz'], + want => "xyz\n", + }, + { + desc => 'removes one trailing newline (before adding a newline)', + args => ["xyz \n\t\n\n"], + want => "xyz \n\t\n\n", + }, + { + desc => 'accepts msg keyword parameter', + args => [msg => 'xyz'], + want => "xyz\n", + }, + { + desc => 'msg keyword parameter trumps message parameter', + args => [msg => 'kw', 'pos'], + want => "kw\n", + }, + { + desc => 'msg keyword parameter trumps message parameter', + args => [msg => 'kw', 'pos'], + want => "kw\n", + }, + { + desc => 'email appends to email body', + args => [email => 1, 'foo'], + init_email => "preexisting message\n", + want_email => "preexisting message\nfoo\n", + want => "foo\n", + }, + { + desc => 'single-line prefix', + args => [pfx => 'PFX:', 'foo'], + want => "PFX: foo\n", + }, + { + desc => 'multi-line prefix', + args => [pfx => 'PFX:', "foo\nbar"], + want => "PFX: foo\nPFX: bar\n", + }, + { + desc => 'single-line long prefix', + args => [pfx => 'VERY LONG PREFIX:', 'foo'], + want => "VERY LONG PREFIX: foo\n", + }, + { + desc => 'multi-line long prefix', + args => [pfx => 'VERY LONG PREFIX:', "foo\nbar"], + want => "VERY LONG PREFIX: foo\nVERY LONG PREFIX: bar\n", + }, + { + desc => 'single line, no prefix, file', + args => ['foo'], + file => 'name', + want => "file name: foo\n", + }, + { + desc => 'single line, no prefix, file, and line number', + args => ['foo'], + file => 'name', + lineno => 42, + want => "file name, line 42: foo\n", + }, + { + desc => 'single line, prefix, file, and line number', + args => [pfx => 'PFX:', 'foo'], + file => 'name', + lineno => 42, + want => "PFX: file name, line 42: foo\n", + }, + { + desc => 'multiple lines, prefix, file, and line number', + args => [pfx => 'PFX:', "foo\nbar"], + file => 'name', + lineno => 42, + want => "PFX: file name, line 42: foo\nPFX: file name, line 42: bar\n", + }, +); + +for my $tc (@test_cases) { + subtest $tc->{desc} => sub { + $tc->{wantemail} //= ''; + my $output; + open(my $fh, '>', \$output); + $ddclient::emailbody = $tc->{init_email} // ''; + local $ddclient::file = $tc->{file} // ''; + $ddclient::file if 0; # suppress spurious warning "Name used only once: possible typo" + local $ddclient::lineno = $tc->{lineno} // ''; + $ddclient::lineno if 0; # suppress spurious warning "Name used only once: possible typo" + ddclient::logmsg(fh => $fh, @{$tc->{args}}); + close($fh); + is($output, $tc->{want}, 'output text matches'); + is($ddclient::emailbody, $tc->{want_email} // '', 'email content matches'); + } +} + +done_testing(); From d6693e0175a84c983bedbecc3bf8464f12114d7d Mon Sep 17 00:00:00 2001 From: Richard Hansen Date: Wed, 22 May 2024 18:16:21 -0400 Subject: [PATCH 3/6] Use the de facto standard signature separator instead of "regards" --- ddclient.in | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ddclient.in b/ddclient.in index 9672440..52a03c6 100755 --- a/ddclient.in +++ b/ddclient.in @@ -2318,7 +2318,7 @@ sub sendmail { "\r\n", $emailbody, "", - "regards,", + "-- ", # https://en.wikipedia.org/wiki/Signature_block#Standard_delimiter " $program\@$hostname (version $version)" ); } From bcd57b486b499e355b9df470b898c5feed89b346 Mon Sep 17 00:00:00 2001 From: Richard Hansen Date: Wed, 22 May 2024 18:20:19 -0400 Subject: [PATCH 4/6] Always log to STDERR, even for debug, info, etc. Rationale: * Logging to STDERR enables separation of processable output (e.g., `--version` or `--help`) and ephemeral status/error messages. * A single file descriptor for all log messages makes it easier for users to capture all log messages. * Consistency: it's what most utilities do. --- ChangeLog.md | 2 ++ ddclient.in | 18 +++++++++--------- 2 files changed, 11 insertions(+), 9 deletions(-) diff --git a/ChangeLog.md b/ChangeLog.md index b8e2766..5608088 100644 --- a/ChangeLog.md +++ b/ChangeLog.md @@ -13,6 +13,8 @@ repository history](https://github.com/ddclient/ddclient/commits/master). * The default web service for `--webv4` and `--webv6` has changed from Google Domains (which is shutting down) to ipify. [5b104ad1](https://github.com/ddclient/ddclient/commit/5b104ad116c023c3760129cab6e141f04f72b406) + * All log messages are now written to STDERR, not a mix of STDOUT and STDERR. + [#676](https://github.com/ddclient/ddclient/pull/676) ### New features diff --git a/ddclient.in b/ddclient.in index 52a03c6..3ae7cdb 100755 --- a/ddclient.in +++ b/ddclient.in @@ -2420,15 +2420,15 @@ sub logmsg { } } } -sub msg { logmsg(fh => *STDOUT, sprintf(shift, @_)); } -sub verbose { logmsg(fh => *STDOUT, email => 1, pfx => pop, sprintf(shift, @_)) if opt('verbose'); } -sub info { logmsg(fh => *STDOUT, email => 1, pfx => 'INFO:', sprintf(shift, @_)) if opt('verbose'); } -sub debug { logmsg(fh => *STDOUT, pfx => 'DEBUG:', sprintf(shift, @_)) if opt('debug'); } -sub debug2 { logmsg(fh => *STDOUT, pfx => 'DEBUG:', sprintf(shift, @_)) if opt('debug') && opt('verbose'); } -sub warning { logmsg( email => 1, pfx => 'WARNING:', sprintf(shift, @_)); } -sub fatal { logmsg( email => 1, pfx => 'FATAL:', sprintf(shift, @_)); sendmail(); exit(1); } -sub success { logmsg(fh => *STDOUT, email => 1, pfx => 'SUCCESS:', sprintf(shift, @_)); } -sub failed { logmsg( email => 1, pfx => 'FAILED:', sprintf(shift, @_)); $result = 'FAILED'; } +sub msg { logmsg( sprintf(shift, @_)); } +sub verbose { logmsg(email => 1, pfx => pop, sprintf(shift, @_)) if opt('verbose'); } +sub info { logmsg(email => 1, pfx => 'INFO:', sprintf(shift, @_)) if opt('verbose'); } +sub debug { logmsg( pfx => 'DEBUG:', sprintf(shift, @_)) if opt('debug'); } +sub debug2 { logmsg( pfx => 'DEBUG:', sprintf(shift, @_)) if opt('debug') && opt('verbose'); } +sub warning { logmsg(email => 1, pfx => 'WARNING:', sprintf(shift, @_)); } +sub fatal { logmsg(email => 1, pfx => 'FATAL:', sprintf(shift, @_)); sendmail(); exit(1); } +sub success { logmsg(email => 1, pfx => 'SUCCESS:', sprintf(shift, @_)); } +sub failed { logmsg(email => 1, pfx => 'FAILED:', sprintf(shift, @_)); $result = 'FAILED'; } sub prettytime { return scalar(localtime(shift)); } sub prettyinterval { From ff39ce3874c89586913080816bafe8edb7592ea5 Mon Sep 17 00:00:00 2001 From: Richard Hansen Date: Wed, 22 May 2024 19:16:16 -0400 Subject: [PATCH 5/6] Don't use `sprintf` if there is only one argument This avoids problems when logging a string that might have metacharacters. --- ddclient.in | 19 ++++++++++--------- t/logmsg.pl | 18 ++++++++++++++++++ 2 files changed, 28 insertions(+), 9 deletions(-) diff --git a/ddclient.in b/ddclient.in index 3ae7cdb..d9d600d 100755 --- a/ddclient.in +++ b/ddclient.in @@ -2420,15 +2420,16 @@ sub logmsg { } } } -sub msg { logmsg( sprintf(shift, @_)); } -sub verbose { logmsg(email => 1, pfx => pop, sprintf(shift, @_)) if opt('verbose'); } -sub info { logmsg(email => 1, pfx => 'INFO:', sprintf(shift, @_)) if opt('verbose'); } -sub debug { logmsg( pfx => 'DEBUG:', sprintf(shift, @_)) if opt('debug'); } -sub debug2 { logmsg( pfx => 'DEBUG:', sprintf(shift, @_)) if opt('debug') && opt('verbose'); } -sub warning { logmsg(email => 1, pfx => 'WARNING:', sprintf(shift, @_)); } -sub fatal { logmsg(email => 1, pfx => 'FATAL:', sprintf(shift, @_)); sendmail(); exit(1); } -sub success { logmsg(email => 1, pfx => 'SUCCESS:', sprintf(shift, @_)); } -sub failed { logmsg(email => 1, pfx => 'FAILED:', sprintf(shift, @_)); $result = 'FAILED'; } +sub _logmsg_fmt { return (@_ > 1) ? sprintf(shift, @_) : shift; } +sub msg { logmsg( _logmsg_fmt(@_)); } +sub verbose { logmsg(email => 1, pfx => shift, _logmsg_fmt(@_)) if opt('verbose'); } +sub info { logmsg(email => 1, pfx => 'INFO:', _logmsg_fmt(@_)) if opt('verbose'); } +sub debug { logmsg( pfx => 'DEBUG:', _logmsg_fmt(@_)) if opt('debug'); } +sub debug2 { logmsg( pfx => 'DEBUG:', _logmsg_fmt(@_)) if opt('debug') && opt('verbose'); } +sub warning { logmsg(email => 1, pfx => 'WARNING:', _logmsg_fmt(@_)); } +sub fatal { logmsg(email => 1, pfx => 'FATAL:', _logmsg_fmt(@_)); sendmail(); exit(1); } +sub success { logmsg(email => 1, pfx => 'SUCCESS:', _logmsg_fmt(@_)); } +sub failed { logmsg(email => 1, pfx => 'FAILED:', _logmsg_fmt(@_)); $result = 'FAILED'; } sub prettytime { return scalar(localtime(shift)); } sub prettyinterval { diff --git a/t/logmsg.pl b/t/logmsg.pl index ccc43d2..47bc0cb 100644 --- a/t/logmsg.pl +++ b/t/logmsg.pl @@ -118,4 +118,22 @@ for my $tc (@test_cases) { } } +{ + my $output; + open(my $fh, '>', \$output); + local *STDERR = $fh; + ddclient::msg('%%'); + close($fh); + is($output, "%%\n", 'single argument is printed directly, not via sprintf'); +} + +{ + my $output; + open(my $fh, '>', \$output); + local *STDERR = $fh; + ddclient::msg('%s', 'foo'); + close($fh); + is($output, "foo\n", 'multiple arguments are formatted via sprintf'); +} + done_testing(); From 9c6e5fdda474ce24ef66fd696ddf47c67baf49e3 Mon Sep 17 00:00:00 2001 From: Richard Hansen Date: Wed, 22 May 2024 19:28:03 -0400 Subject: [PATCH 6/6] Output a `|` character in log message continuation lines This makes it easier to tell where multi-line log messages begin and end. --- ChangeLog.md | 3 +++ ddclient.in | 5 +++-- t/logmsg.pl | 16 ++++++++-------- 3 files changed, 14 insertions(+), 10 deletions(-) diff --git a/ChangeLog.md b/ChangeLog.md index 5608088..d0ca95c 100644 --- a/ChangeLog.md +++ b/ChangeLog.md @@ -38,6 +38,9 @@ repository history](https://github.com/ddclient/ddclient/commits/master). [#639](https://github.com/ddclient/ddclient/pull/639) * Updated sample systemd service unit file to improve logging in the systemd journal. [#669](https://github.com/ddclient/ddclient/pull/669) + * The second and subsequent lines in a multi-line log message are now prefixed + with a `|` character. + [#676](https://github.com/ddclient/ddclient/pull/676) ### Bug fixes diff --git a/ddclient.in b/ddclient.in index d9d600d..f6bf5ae 100755 --- a/ddclient.in +++ b/ddclient.in @@ -2398,14 +2398,15 @@ sub logmsg { chomp($buffer); my $prefix = $args{pfx}; - $prefix = sprintf "%-9s ", $prefix if $prefix; + $prefix = sprintf "%-9s ", $prefix if $prefix; if ($file) { $prefix .= "file $file"; $prefix .= ", line $lineno" if $lineno; - $prefix .= ": "; + $prefix .= ": "; } if ($prefix) { $buffer = "$prefix$buffer"; + $prefix =~ s/ $/| /; $buffer =~ s/\n/\n$prefix/g; } $buffer .= "\n"; diff --git a/t/logmsg.pl b/t/logmsg.pl index 47bc0cb..347a69e 100644 --- a/t/logmsg.pl +++ b/t/logmsg.pl @@ -55,49 +55,49 @@ my @test_cases = ( { desc => 'single-line prefix', args => [pfx => 'PFX:', 'foo'], - want => "PFX: foo\n", + want => "PFX: foo\n", }, { desc => 'multi-line prefix', args => [pfx => 'PFX:', "foo\nbar"], - want => "PFX: foo\nPFX: bar\n", + want => "PFX: foo\nPFX: | bar\n", }, { desc => 'single-line long prefix', args => [pfx => 'VERY LONG PREFIX:', 'foo'], - want => "VERY LONG PREFIX: foo\n", + want => "VERY LONG PREFIX: foo\n", }, { desc => 'multi-line long prefix', args => [pfx => 'VERY LONG PREFIX:', "foo\nbar"], - want => "VERY LONG PREFIX: foo\nVERY LONG PREFIX: bar\n", + want => "VERY LONG PREFIX: foo\nVERY LONG PREFIX:| bar\n", }, { desc => 'single line, no prefix, file', args => ['foo'], file => 'name', - want => "file name: foo\n", + want => "file name: foo\n", }, { desc => 'single line, no prefix, file, and line number', args => ['foo'], file => 'name', lineno => 42, - want => "file name, line 42: foo\n", + want => "file name, line 42: foo\n", }, { desc => 'single line, prefix, file, and line number', args => [pfx => 'PFX:', 'foo'], file => 'name', lineno => 42, - want => "PFX: file name, line 42: foo\n", + want => "PFX: file name, line 42: foo\n", }, { desc => 'multiple lines, prefix, file, and line number', args => [pfx => 'PFX:', "foo\nbar"], file => 'name', lineno => 42, - want => "PFX: file name, line 42: foo\nPFX: file name, line 42: bar\n", + want => "PFX: file name, line 42: foo\nPFX: file name, line 42:| bar\n", }, );