Merge pull request #676 from rhansen/logging

Various minor logging improvements

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
 
@@ -36,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
 

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 \

ddclient.in

@@ -125,8 +125,8 @@ if ($program =~ /test/i) {
     $savedir = 'URL';
 }
 
-my $msgs      = '';
+our $emailbody = '';
-my $last_msgs = '';
+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,",
+                "-- ",  # https://en.wikipedia.org/wiki/Signature_block#Standard_delimiter
                 "   $program\@$hostname (version $version)"
         );
     }
-    $last_msgs = $msgs;
+    $last_emailbody = $emailbody;
-    $msgs      = '';
+    $emailbody      = '';
 }
 ######################################################################
 ##  split_by_comma
@@ -2382,50 +2382,55 @@ sub ynu {
     return $undef;
 }
 ######################################################################
-## msg
+## Logging
-## debug
-## warning
-## fatal
 ######################################################################
-my $_in_msg = 0;
+my $_in_logmsg = 0;
-sub _msg {
+sub logmsg {
-    my $fh     = shift;
+    my %args = (
-    my $log    = shift;
+        msg => '',
-    my $prefix = shift;
+        pfx => '',
-    my $format = shift;
+        fh => *STDERR,
-    my $buffer = sprintf $format, @_;
+        email => 0,  # If truthy, the message is also included in the next email.
+        (@_ % 2) ? (msg => pop) : (),
+        @_,
+    );
+    my $buffer = $args{msg};
     chomp($buffer);
 
-    $prefix = sprintf "%-9s ", $prefix if $prefix;
+    my $prefix = $args{pfx};
+    $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";
-    print $fh $buffer;
+    print({$args{fh}} $buffer);
 
-    $msgs .= $buffer if $log;
+    if ($args{email}) {
-    if ($log && !$_in_msg) {
+        $emailbody .= $buffer;
-        ++$_in_msg;  # avoid infinite recursion if logger calls _msg
+        if (!$_in_logmsg) {
-        logger($buffer);
+            ++$_in_logmsg;  # avoid infinite recursion if logger calls logmsg
-        --$_in_msg;
+            logger($buffer);
+            --$_in_logmsg;
+        }
     }
-
 }
-sub msg     { _msg(*STDOUT, 0, '',         @_);                                   }
+sub _logmsg_fmt { return (@_ > 1) ? sprintf(shift, @_) : shift; }
-sub verbose { _msg(*STDOUT, 1, @_)             if opt('verbose');                 }
+sub msg     { logmsg(                               _logmsg_fmt(@_)); }
-sub info    { _msg(*STDOUT, 1, 'INFO:',    @_) if opt('verbose');                 }
+sub verbose { logmsg(email => 1, pfx => shift,      _logmsg_fmt(@_)) if opt('verbose'); }
-sub debug   { _msg(*STDOUT, 0, 'DEBUG:',   @_) if opt('debug');                   }
+sub info    { logmsg(email => 1, pfx => 'INFO:',    _logmsg_fmt(@_)) if opt('verbose'); }
-sub debug2  { _msg(*STDOUT, 0, 'DEBUG:',   @_) if opt('debug') && opt('verbose'); }
+sub debug   { logmsg(            pfx => 'DEBUG:',   _logmsg_fmt(@_)) if opt('debug'); }
-sub warning { _msg(*STDERR, 1, 'WARNING:', @_);                                   }
+sub debug2  { logmsg(            pfx => 'DEBUG:',   _logmsg_fmt(@_)) if opt('debug') && opt('verbose'); }
-sub fatal   { _msg(*STDERR, 1, 'FATAL:',   @_); sendmail(); exit(1);              }
+sub warning { logmsg(email => 1, pfx => 'WARNING:', _logmsg_fmt(@_)); }
-sub success { _msg(*STDOUT, 1, 'SUCCESS:', @_);                                   }
+sub fatal   { logmsg(email => 1, pfx => 'FATAL:',   _logmsg_fmt(@_)); sendmail(); exit(1); }
-sub failed  { _msg(*STDERR, 1, 'FAILED:',  @_); $result = 'FAILED';               }
+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 {

t/logmsg.pl

@@ -0,0 +1,139 @@
+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');
+    }
+}
+
+{
+    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();