Merge pull request #725 from rhansen/logging

Add context to log messages

ChangeLog.md

@@ -72,6 +72,8 @@ repository history](https://github.com/ddclient/ddclient/commits/master).
     different prefix to distinguish them from separate log messages.
     [#676](https://github.com/ddclient/ddclient/pull/676)
     [#719](https://github.com/ddclient/ddclient/pull/719)
+  * Log messages now include context, making it easier to troubleshoot issues.
+    [#725](https://github.com/ddclient/ddclient/pull/725)
   * `emailonly`: New `protocol` option that simply emails you when your IP
     address changes.  [#654](https://github.com/ddclient/ddclient/pull/654)
   * `he.net`: Added support for updating Hurricane Electric records.

t/header_ok.pl

@@ -63,7 +63,7 @@ my @test_cases = (
 for my $tc (@test_cases) {
     subtest $tc->{desc} => sub {
         $failmsg = '';
-        is(ddclient::header_ok('host', $tc->{input}), $tc->{want}, 'return value matches');
+        is(ddclient::header_ok($tc->{input}), $tc->{want}, 'return value matches');
         SKIP: {
             skip('Test::MockModule not available') if !$have_mock;
             like($failmsg, $tc->{wantmsg} // qr/^$/, 'fail message matches');

t/logmsg.pl

@@ -53,51 +53,58 @@ my @test_cases = (
         want => "foo\n",
     },
     {
-        desc => 'single-line prefix',
+        desc => 'single-line label',
-        args => [pfx => 'PFX:', 'foo'],
+        args => [label => 'LBL', 'foo'],
-        want => "PFX:     > foo\n",
+        want => "LBL:     > foo\n",
     },
     {
-        desc => 'multi-line prefix',
+        desc => 'multi-line label',
-        args => [pfx => 'PFX:', "foo\nbar"],
+        args => [label => 'LBL', "foo\nbar"],
-        want => "PFX:     > foo\nPFX:       bar\n",
+        want => ("LBL:     > foo\n" .
+                 "LBL:       bar\n"),
     },
     {
-        desc => 'single-line long prefix',
+        desc => 'single-line long label',
-        args => [pfx => 'VERY LONG PREFIX:', 'foo'],
+        args => [label => 'VERY LONG LABEL', 'foo'],
-        want => "VERY LONG PREFIX: > foo\n",
+        want => "VERY LONG LABEL: > foo\n",
     },
     {
-        desc => 'multi-line long prefix',
+        desc => 'multi-line long label',
-        args => [pfx => 'VERY LONG PREFIX:', "foo\nbar"],
+        args => [label => 'VERY LONG LABEL', "foo\nbar"],
-        want => "VERY LONG PREFIX: > foo\nVERY LONG PREFIX:   bar\n",
+        want => ("VERY LONG LABEL: > foo\n" .
+                 "VERY LONG LABEL:   bar\n"),
     },
     {
-        desc => 'single line, no prefix, file',
+        desc => 'single line, no label, single context',
         args => ['foo'],
-        file => 'name',
+        ctxs => ['only context'],
-        want => "file name: > foo\n",
+        want => "[only context]> foo\n",
     },
     {
-        desc => 'single line, no prefix, file, and line number',
+        desc => 'single line, no label, two contexts',
         args => ['foo'],
-        file => 'name',
+        ctxs => ['context one', 'context two'],
-        lineno => 42,
+        want => "[context one][context two]> foo\n",
-        want => "file name, line 42: > foo\n",
     },
     {
-        desc => 'single line, prefix, file, and line number',
+        desc => 'single line, label, two contexts',
-        args => [pfx => 'PFX:', 'foo'],
+        args => [label => 'LBL', 'foo'],
-        file => 'name',
+        ctxs => ['context one', 'context two'],
-        lineno => 42,
+        want => "LBL:     [context one][context two]> foo\n",
-        want => "PFX:     file name, line 42: > foo\n",
     },
     {
-        desc => 'multiple lines, prefix, file, and line number',
+        desc => 'multiple lines, label, two contexts',
-        args => [pfx => 'PFX:', "foo\nbar"],
+        args => [label => 'LBL', "foo\nbar"],
-        file => 'name',
+        ctxs => ['context one', 'context two'],
-        lineno => 42,
+        want => ("LBL:     [context one][context two]> foo\n" .
-        want => "PFX:     file name, line 42: > foo\nPFX:     file name, line 42:   bar\n",
+                 "LBL:     [context one][context two]  bar\n"),
+    },
+    {
+        desc => 'ctx arg',
+        args => [label => 'LBL', ctx => 'three', "foo\nbar"],
+        ctxs => ['one', 'two'],
+        want => ("LBL:     [one][two][three]> foo\n" .
+                 "LBL:     [one][two][three]  bar\n"),
     },
 );
 
@@ -107,10 +114,8 @@ for my $tc (@test_cases) {
         my $output;
         open(my $fh, '>', \$output);
         $ddclient::emailbody = $tc->{init_email} // '';
-        local $ddclient::file = $tc->{file} // '';
+        local $ddclient::_l = $ddclient::_l;
-        $ddclient::file if 0;  # suppress spurious warning "Name used only once: possible typo"
+        $ddclient::_l = ddclient::pushlogctx($_) for @{$tc->{ctxs} // []};
-        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');
@@ -118,24 +123,38 @@ for my $tc (@test_cases) {
     }
 }
 
-{
+my @logfmt_test_cases = (
-    my $output;
+    {
-    open(my $fh, '>', \$output);
+        desc => 'single argument is printed directly, not via sprintf',
-    local *STDERR = $fh;
+        args => ['%%'],
-    local $ddclient::globals{debug} = 1;
+        want => "DEBUG:   > %%\n",
-    ddclient::debug('%%');
+    },
-    close($fh);
+    {
-    is($output, "DEBUG:   > %%\n", 'single argument is printed directly, not via sprintf');
+        desc => 'multiple arguments are formatted via sprintf',
-}
+        args => ['%s', 'foo'],
+        want => "DEBUG:   > foo\n",
+    },
+    {
+        desc => 'single argument with context',
+        args => [ctx => 'context', '%%'],
+        want => "DEBUG:   [context]> %%\n",
+    },
+    {
+        desc => 'multiple arguments with context',
+        args => [ctx => 'context', '%s', 'foo'],
+        want => "DEBUG:   [context]> foo\n",
+    },
+);
 
-{
+for my $tc (@logfmt_test_cases) {
-    my $output;
+    my $got;
-    open(my $fh, '>', \$output);
+    open(my $fh, '>', \$got);
     local *STDERR = $fh;
     local $ddclient::globals{debug} = 1;
-    ddclient::debug('%s', 'foo');
+    %ddclient::globals if 0;
+    ddclient::debug(@{$tc->{args}});
     close($fh);
-    is($output, "DEBUG:   > foo\n", 'multiple arguments are formatted via sprintf');
+    is($got, $tc->{want}, $tc->{desc});
 }
 
 done_testing();