bug#50009: 28.0.50; add CRLF to outgoing ERC protocol logger lines

["J.P." <jp@neverwas.me>]

[-- Attachment #1: Type: text/plain, Size: 165 bytes --]

v2. Tweaked some spacing and borrowed a unit test from bug#48598.

(Note: the first attachment just shows the changes from the last set and
is not itself a patch.)


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0000-v1-v2.diff --]
[-- Type: text/x-patch, Size: 4516 bytes --]

From c4127a84f084166f2267c9745d1fc1f06ebbead2 Mon Sep 17 00:00:00 2001
From: "F. Jason Park" <jp@neverwas.me>
Date: Sun, 12 Sep 2021 04:44:23 -0700
Subject: [PATCH 0/1] *** SUBJECT HERE ***

*** BLURB HERE ***

F. Jason Park (1):
  Add CRLF to outgoing ERC protocol logger lines

 lisp/erc/erc.el            | 79 ++++++++++++++++++++++++--------------
 test/lisp/erc/erc-tests.el | 35 +++++++++++++++++
 2 files changed, 86 insertions(+), 28 deletions(-)

Interdiff:
diff --git a/lisp/erc/erc.el b/lisp/erc/erc.el
index f5ecb043b0..ead82b794d 100644
--- a/lisp/erc/erc.el
+++ b/lisp/erc/erc.el
@@ -2313,12 +2313,11 @@ erc-error
 ;;; Debugging the protocol
 
 (defvar erc-debug-irc-protocol-time-format "%FT%T.%6N%z "
-  "An optional format string for optional I/O timestamps.")
+  "Timestamp format string for protocol logger.")
 
 (defconst erc-debug-irc-protocol-version "1"
   "Protocol log format version number.
-These logs are machine-readable, but external tools used in bug
-reproduction, etc. need a way to track changes to the format.")
+This is to help tooling track changes to the format.")
 
 (defvar erc-debug-irc-protocol nil
   "If non-nil, log all IRC protocol traffic to the buffer \"*erc-protocol*\".
@@ -2384,8 +2383,8 @@ erc-toggle-debug-irc-protocol
   "Toggle the value of `erc-debug-irc-protocol'.
 
 If ARG is non-nil, show the *erc-protocol* buffer.  Everything before
-the first CRLF is front matter.  Everything before the first double
-linefeed is a header."
+and including the first double CRLF is front matter.  Everything before
+the first double linefeed is a header."
   (interactive "P")
   (let* ((buf (get-buffer-create "*erc-protocol*")))
     (with-current-buffer buf
@@ -2409,10 +2408,12 @@ erc-toggle-debug-irc-protocol
       ;; Searchable phrase printed twice between logs and once before
       ;; the first. This is a single line with CRLF endings.
       (let ((inhibit-read-only t))
-        (insert (erc-make-notice
-                 (format "IRC protocol logging %s at %s\r\n"
+        (insert (if erc-debug-irc-protocol "\r\n" "")
+                (erc-make-notice
+                 (format "IRC protocol logging %s at %s"
                          (if erc-debug-irc-protocol "disabled" "enabled")
-                         (current-time-string))))))
+                         (current-time-string)))
+                (if erc-debug-irc-protocol "\r\n" "\r\n\r\n"))))
     (setq erc-debug-irc-protocol (not erc-debug-irc-protocol))
     (if (and arg
              (not (get-buffer-window "*erc-protocol*" t)))
diff --git a/test/lisp/erc/erc-tests.el b/test/lisp/erc/erc-tests.el
index d13397274a..5a362628fa 100644
--- a/test/lisp/erc/erc-tests.el
+++ b/test/lisp/erc/erc-tests.el
@@ -24,6 +24,7 @@
 (require 'ert)
 (require 'erc)
 (require 'erc-ring)
+(require 'erc-networks)
 
 (ert-deftest erc--read-time-period ()
   (cl-letf (((symbol-function 'read-string) (lambda (&rest _) "")))
@@ -109,3 +110,37 @@ erc-ring-previous-command
         (should (looking-at "abc")))))
   (when noninteractive
     (kill-buffer "*#fake*")))
+
+(ert-deftest erc-log-irc-protocol ()
+  (should-not erc-debug-irc-protocol)
+  (with-temp-buffer
+    (let (erc-server-announced-name
+          erc-network
+          (erc-server-process (start-process "fake" (current-buffer) "true"))
+          (erc-server-current-nick "tester")
+          (erc-session-server "myproxy.localhost")
+          (erc-session-port 6667)
+          (inhibit-message t))
+      (erc-toggle-debug-irc-protocol)
+      (erc-log-irc-protocol "PASS changeme\r\n" 'outgoing)
+      (setq erc-server-announced-name "irc.gnu.org")
+      (erc-log-irc-protocol ":irc.gnu.org 001 tester :Welcome")
+      (erc-log-irc-protocol ":irc.gnu.org 002 tester :Your host is irc.gnu.org")
+      (setq erc-network 'FooNet)
+      (erc-log-irc-protocol ":irc.gnu.org 422 tester :MOTD missing")
+      (setq erc-network 'BarNet)
+      (erc-log-irc-protocol ":irc.gnu.org 221 tester +i")))
+  (with-current-buffer "*erc-protocol*"
+    (goto-char (point-min))
+    (search-forward "myproxy.localhost:6667 >> PASS")
+    (forward-line)
+    (search-forward "irc.gnu.org << :irc.gnu.org 001")
+    (forward-line)
+    (search-forward "irc.gnu.org << :irc.gnu.org 002")
+    (forward-line)
+    (search-forward "FooNet << :irc.gnu.org 422")
+    (forward-line)
+    (search-forward "BarNet << :irc.gnu.org 221"))
+  (when noninteractive
+    (kill-buffer "*erc-protocol*")
+    (should-not erc-debug-irc-protocol)))
-- 
2.31.1


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #3: 0001-Add-CRLF-to-outgoing-ERC-protocol-logger-lines.patch --]
[-- Type: text/x-patch, Size: 9130 bytes --]

From c4127a84f084166f2267c9745d1fc1f06ebbead2 Mon Sep 17 00:00:00 2001
From: "F. Jason Park" <jp@neverwas.me>
Date: Mon, 14 Jun 2021 22:24:01 -0700
Subject: [PATCH 1/1] Add CRLF to outgoing ERC protocol logger lines

* erc.el (erc-debug-irc-protocol): Fix line-ending mismatch between
incoming and outgoing logger lines without changing interface. Do this
by adding carriage returns to the latter to improve machine
readability. Change printed peer labels to most accurately reflect
logical endpoints.

(erc-debug-irc-protocol-time-format): Add new variable to support
timestamps in protocol logger output.

(erc-debug-irc-protocol-version): Add new variable to help tooling
track logging format independent of ERC and Emacs versions.

(erc-toggle-debug-irc-protocol): Add headers to protocol-log buffer
to aid future bug-reproduction tools. Clean up overlong lines.

This is bug#50009.
---
 lisp/erc/erc.el            | 79 ++++++++++++++++++++++++--------------
 test/lisp/erc/erc-tests.el | 35 +++++++++++++++++
 2 files changed, 86 insertions(+), 28 deletions(-)

diff --git a/lisp/erc/erc.el b/lisp/erc/erc.el
index e0fda41f8e..ead82b794d 100644
--- a/lisp/erc/erc.el
+++ b/lisp/erc/erc.el
@@ -2312,6 +2312,13 @@ erc-error
 
 ;;; Debugging the protocol
 
+(defvar erc-debug-irc-protocol-time-format "%FT%T.%6N%z "
+  "Timestamp format string for protocol logger.")
+
+(defconst erc-debug-irc-protocol-version "1"
+  "Protocol log format version number.
+This is to help tooling track changes to the format.")
+
 (defvar erc-debug-irc-protocol nil
   "If non-nil, log all IRC protocol traffic to the buffer \"*erc-protocol*\".
 
@@ -2333,32 +2340,36 @@ erc-log-irc-protocol
 
 The buffer is created if it doesn't exist.
 
-If OUTBOUND is non-nil, STRING is being sent to the IRC server
-and appears in face `erc-input-face' in the buffer."
+If OUTBOUND is non-nil, STRING is being sent to the IRC server and
+appears in face `erc-input-face' in the buffer.  Lines must already
+contain CRLF endings.  Peer is identified by the most precise label
+available at run time, starting with the network name, followed by the
+self-reported host name, and falling back to the dialed <server>:<port>.
+When capturing logs for multiple peers and sorting them into buckets,
+such inconsistent labeling may pose a problem during an initial server
+burst.  For now, the recommended approach is to wrap this function with
+advice that temporarily redefines the symbol-function `erc-network'."
   (when erc-debug-irc-protocol
-    (let ((network-name (or (ignore-errors (erc-network-name))
-                            "???")))
+    (let ((esid (or (and (fboundp 'erc-network)
+                         (erc-network)
+                         (erc-network-name))
+                    erc-server-announced-name
+                    (format "%s:%s" erc-session-server erc-session-port)))
+          (ts (when erc-debug-irc-protocol-time-format
+                (format-time-string erc-debug-irc-protocol-time-format))))
       (with-current-buffer (get-buffer-create "*erc-protocol*")
         (save-excursion
           (goto-char (point-max))
           (let ((inhibit-read-only t))
-            (insert (if (not outbound)
-                        ;; Cope with the fact that string might
-                        ;; contain multiple lines of text.
-                        (let ((lines (delete "" (split-string string
-                                                              "\n\\|\r\n")))
-                              (result ""))
-                          (dolist (line lines)
-                            (setq result (concat result network-name
-                                                 " << " line "\n")))
-                          result)
-                      (propertize
-                       (concat network-name " >> " string
-                               (if (/= ?\n
-                                       (aref string
-                                             (1- (length string))))
-                                   "\n"))
-                       'font-lock-face 'erc-input-face)))))
+            (insert (if outbound
+                        (concat ts esid " >> " string)
+                      ;; Cope with multi-line messages
+                      (let ((lines (split-string string "[\r\n]+" t))
+                            result)
+                        (dolist (line lines)
+                          (setq result (concat result ts esid
+                                               " << " line "\r\n")))
+                        result)))))
         (let ((orig-win (selected-window))
               (debug-buffer-window (get-buffer-window (current-buffer) t)))
           (when debug-buffer-window
@@ -2371,26 +2382,38 @@ erc-log-irc-protocol
 (defun erc-toggle-debug-irc-protocol (&optional arg)
   "Toggle the value of `erc-debug-irc-protocol'.
 
-If ARG is non-nil, show the *erc-protocol* buffer."
+If ARG is non-nil, show the *erc-protocol* buffer.  Everything before
+and including the first double CRLF is front matter.  Everything before
+the first double linefeed is a header."
   (interactive "P")
   (let* ((buf (get-buffer-create "*erc-protocol*")))
     (with-current-buffer buf
       (view-mode-enter)
       (when (null (current-local-map))
-        (let ((inhibit-read-only t))
-          (insert (erc-make-notice "This buffer displays all IRC protocol traffic exchanged with each server.\n"))
-          (insert (erc-make-notice "Kill this buffer to terminate protocol logging.\n\n")))
+        (let ((inhibit-read-only t)
+              (headers (concat "Version: " erc-debug-irc-protocol-version "\n"
+                               "Emacs-Version: " emacs-version "\n"
+                               "\n"))
+              (msg (concat "This buffer displays all IRC protocol traffic "
+                           "exchanged with servers.\n"
+                           "Kill it to disable logging.\n"
+                           "Press `t' to toggle.\n")))
+          (insert headers (erc-make-notice msg)))
         (use-local-map (make-sparse-keymap))
         (local-set-key (kbd "t") 'erc-toggle-debug-irc-protocol))
       (add-hook 'kill-buffer-hook
                 (lambda () (setq erc-debug-irc-protocol nil))
                 nil 'local)
       (goto-char (point-max))
+      ;; Searchable phrase printed twice between logs and once before
+      ;; the first. This is a single line with CRLF endings.
       (let ((inhibit-read-only t))
-        (insert (erc-make-notice
-                 (format "IRC protocol logging %s at %s -- Press `t' to toggle logging.\n"
+        (insert (if erc-debug-irc-protocol "\r\n" "")
+                (erc-make-notice
+                 (format "IRC protocol logging %s at %s"
                          (if erc-debug-irc-protocol "disabled" "enabled")
-                         (current-time-string))))))
+                         (current-time-string)))
+                (if erc-debug-irc-protocol "\r\n" "\r\n\r\n"))))
     (setq erc-debug-irc-protocol (not erc-debug-irc-protocol))
     (if (and arg
              (not (get-buffer-window "*erc-protocol*" t)))
diff --git a/test/lisp/erc/erc-tests.el b/test/lisp/erc/erc-tests.el
index d13397274a..5a362628fa 100644
--- a/test/lisp/erc/erc-tests.el
+++ b/test/lisp/erc/erc-tests.el
@@ -24,6 +24,7 @@
 (require 'ert)
 (require 'erc)
 (require 'erc-ring)
+(require 'erc-networks)
 
 (ert-deftest erc--read-time-period ()
   (cl-letf (((symbol-function 'read-string) (lambda (&rest _) "")))
@@ -109,3 +110,37 @@ erc-ring-previous-command
         (should (looking-at "abc")))))
   (when noninteractive
     (kill-buffer "*#fake*")))
+
+(ert-deftest erc-log-irc-protocol ()
+  (should-not erc-debug-irc-protocol)
+  (with-temp-buffer
+    (let (erc-server-announced-name
+          erc-network
+          (erc-server-process (start-process "fake" (current-buffer) "true"))
+          (erc-server-current-nick "tester")
+          (erc-session-server "myproxy.localhost")
+          (erc-session-port 6667)
+          (inhibit-message t))
+      (erc-toggle-debug-irc-protocol)
+      (erc-log-irc-protocol "PASS changeme\r\n" 'outgoing)
+      (setq erc-server-announced-name "irc.gnu.org")
+      (erc-log-irc-protocol ":irc.gnu.org 001 tester :Welcome")
+      (erc-log-irc-protocol ":irc.gnu.org 002 tester :Your host is irc.gnu.org")
+      (setq erc-network 'FooNet)
+      (erc-log-irc-protocol ":irc.gnu.org 422 tester :MOTD missing")
+      (setq erc-network 'BarNet)
+      (erc-log-irc-protocol ":irc.gnu.org 221 tester +i")))
+  (with-current-buffer "*erc-protocol*"
+    (goto-char (point-min))
+    (search-forward "myproxy.localhost:6667 >> PASS")
+    (forward-line)
+    (search-forward "irc.gnu.org << :irc.gnu.org 001")
+    (forward-line)
+    (search-forward "irc.gnu.org << :irc.gnu.org 002")
+    (forward-line)
+    (search-forward "FooNet << :irc.gnu.org 422")
+    (forward-line)
+    (search-forward "BarNet << :irc.gnu.org 221"))
+  (when noninteractive
+    (kill-buffer "*erc-protocol*")
+    (should-not erc-debug-irc-protocol)))
-- 
2.31.1