lacme-account: Improve log messages.

Again…

5 files changed, 21 insertions, 19 deletions

diff --git a/Changelog b/Changelog
index 3765bf9..faf32a8 100644
--- a/Changelog
+++ b/Changelog
@@ -1,5 +1,6 @@
 lacme (0.8.1) upstream;
 
+ + lacme-accountd: improve log messages.
  - lacme: in the [accountd] config, let lacme-accountd(1) do the
    %-expansion for 'config', not lacme(8) when building the command.
 
diff --git a/lacme-accountd b/lacme-accountd
index 5794ec1..68d0f39 100755
--- a/lacme-accountd
+++ b/lacme-accountd
@@ -83,7 +83,8 @@ sub error(@) {
 }
 sub panic(@) {
     my @loc = caller;
-    my @msg = (@_, " at line $loc[2] in $loc[1]");
+    my @msg = ("PANIC at line $loc[2] in $loc[1]");
+    push @msg, ": ", @_ if @_;
     info(@msg);
     exit 255;
 }
@@ -234,29 +235,29 @@ sub conn($$$) {
     $out->printflush( "$PROTOCOL_VERSION OK ", $EXTRA_GREETING_STR, "\r\n",
         $JWK_STR, "\r\n" ) or warn "print: $!";
 
-    # sign whatever comes in
     while (defined (my $data = $in->getline())) {
         $data =~ s/\r\n\z// or panic();
 
+        # validate JWS Signing Input from RFC 7515:
+        # ASCII(BASE64URL(UTF8(JWS Protected Header)) || '.' || BASE64URL(JWS Payload))
         my ($header, $payload) = split(/\./, $data, 2);
         if (defined $header and $header =~ /\A[A-Za-z0-9\-_]+\z/) {
             $header = decode_base64url($header);
         } else {
-            info("[$id] >>> Error: Refusing to sign request: Malformed protected header");
+            info("[$id] NOSIGN [malformed JWS Protected Header]");
             last;
         }
         if (defined $payload and $payload =~ /\A[A-Za-z0-9\-_]*\z/) {
-            # empty payloads are valid, cf. POST-as-GET
+            # empty payloads are valid, and used for POST-as-GET (RFC 8555 sec. 6.3)
             $payload = decode_base64url($payload);
         } else {
-            info("[$id] >>> Error: Refusing to sign request: Malformed payload");
+            info("[$id] NOSIGN [malformed JWS Payload]");
             last;
         }
 
-        my $req = "header=base64url($header); playload=base64url($payload)";
-        logmsg(noquiet => "[$id] >>> OK signing request: ", $req);
-
-        my $sig = $SIGN->($data);
+        my $req = "header=base64url($header) playload=base64url($payload)";
+        my $sig = $SIGN->($data) // panic();
+        logmsg(noquiet => "[$id] SIGNED ", $req);
         $out->printflush( encode_base64url($sig), "\r\n" ) or warn "print: $!";
     }
 }
@@ -270,9 +271,9 @@ if (defined $OPTS{stdio}) {
             next if $! == EINTR; # try again if accept(2) was interrupted by a signal
             panic("accept: $!");
         };
-        logmsg(noquiet => "[$count] >>> Accepted new connection");
+        logmsg(noquiet => "[$count] Accepted new connection");
         conn($conn, $conn, $count);
-        logmsg(noquiet => "[$count] >>> Connection terminated");
+        logmsg(noquiet => "[$count] Connection terminated");
         $conn->close() or warn "close: $!";
     }
 }
diff --git a/tests/accountd b/tests/accountd
index a603c16..7e8fd4c 100644
--- a/tests/accountd
+++ b/tests/accountd
@@ -79,9 +79,9 @@ wait
 
 # ensure signature requests are logged
 grep -Fq "Starting lacme Account Key Manager at /home/lacme-account/S.lacme" ~lacme-account/.local/share/lacme/accountd.log
-grep -Fq "[0] >>> Accepted new connection" ~lacme-account/.local/share/lacme/accountd.log
-grep -Fq "[1] >>> Accepted new connection" ~lacme-account/.local/share/lacme/accountd.log
+grep -Fq "[0] Accepted new connection" ~lacme-account/.local/share/lacme/accountd.log
+grep -Fq "[1] Accepted new connection" ~lacme-account/.local/share/lacme/accountd.log
 grep -Fq "Shutting down and closing lacme Account Key Manager" ~lacme-account/.local/share/lacme/accountd.log
-grep -F ">>> OK signing request:" ~lacme-account/.local/share/lacme/accountd.log
+grep -F "] SIGNED header=base64url({" ~lacme-account/.local/share/lacme/accountd.log
 
 # vim: set filetype=sh :
diff --git a/tests/accountd-kid b/tests/accountd-kid
index e1bd63d..f55facf 100644
--- a/tests/accountd-kid
+++ b/tests/accountd-kid
@@ -28,8 +28,8 @@ runuser -u lacme-account -- lacme-accountd --socket="$SOCKET" --quiet & PID=$!
 ! lacme --socket="$SOCKET" account 2>"$STDERR" || fail
 grepstderr -Fxq "WARNING: lacme-accountd supplied an empty JWK; try removing 'keyid' setting from lacme-accountd.conf if the ACME resource request fails."
 grepstderr -Fxq "400 Bad Request (Parse error reading JWS)"
-! grep -F ">>> OK signing request: header=" ~lacme-account/.local/share/lacme/accountd.log | \
-    grep -vF ">>> OK signing request: header=base64url({\"alg\":\"RS256\",\"jwk\":{}," || exit 1
+grep -F "] SIGNED header=base64url({" ~lacme-account/.local/share/lacme/accountd.log >/tmp/signed
+! grep -vF "] SIGNED header=base64url({\"alg\":\"RS256\",\"jwk\":{}," </tmp/signed
 
 # rotate log and restart accountd
 kill $PID
@@ -53,7 +53,7 @@ kill $PID
 wait
 
 # make sure all signing requests have a KID
-! grep -F ">>> OK signing request: header=" ~lacme-account/.local/share/lacme/accountd.log | \
-    grep -vF ">>> OK signing request: header=base64url({\"alg\":\"RS256\",\"kid\":\"$keyid\"," || exit 1
+grep -F "] SIGNED header=base64url({" ~lacme-account/.local/share/lacme/accountd.log >/tmp/signed
+! grep -vF "] SIGNED header=base64url({\"alg\":\"RS256\",\"kid\":\"$keyid\"," </tmp/signed
 
 # vim: set filetype=sh :
diff --git a/tests/accountd-remote b/tests/accountd-remote
index 9e7f812..ce2b54e 100644
--- a/tests/accountd-remote
+++ b/tests/accountd-remote
@@ -50,6 +50,6 @@ lacme newOrder
 test /etc/lacme/simpletest.rsa.crt -nt /etc/lacme/simpletest.rsa.key
 
 # ensure signature requests are logged
-grep -F ">>> OK signing request:" ~lacme-account/.local/share/lacme/accountd.log
+grep -F "] SIGNED header=base64url({" ~lacme-account/.local/share/lacme/accountd.log
 
 # vim: set filetype=sh :