13

I depend on the *Messages* buffer a lot, but entries are not timestamped.

How can one add a timestamp to each entry in Emacs' Messages buffer?

So that something like this:

Loading /Users/gsl/lisp.d/init.el (source)...
No outline structure detected
For information about GNU Emacs and the GNU system, type C-h C-a.
Loading /Users/gsl/lisp.d/var/recentf...done
Error running timer: (wrong-number-of-arguments (lambda nil (setq gc-cons-threshold (* 64 1024 1024)) (message "WARNING: gc-cons-threshold restored to %S")) 1)
[yas] Prepared just-in-time loading of snippets successfully.
M-] is undefined
CHILDREN [2 times]
‘show-all’ is an obsolete command (as of 25.1); use ‘outline-show-all’ instead.
Invalid face reference: nil [33 times]
Auto-saving...done
Saving file /Users/gsl/lisp.d/init.el...
Wrote /Users/gsl/lisp.d/init.el
mwheel-scroll: Beginning of buffer [5 times]
Mark set
previous-line: Beginning of buffer [10 times]
Quit [4 times]

will become something like this:

2017-02-14-18:50:01 Loading /Users/gsl/lisp.d/init.el (source)...
2017-02-14-18:50:02 No outline structure detected
2017-02-14-18:50:03 For information about GNU Emacs and the GNU system, type C-h C-a.
2017-02-14-18:50:05 Loading /Users/gsl/lisp.d/var/recentf...done
2017-02-14-18:50:10 Error running timer: (wrong-number-of-arguments (lambda nil (setq gc-cons-threshold (* 64 1024 1024)) (message "WARNING: gc-cons-threshold restored     to %S")) 1)
2017-02-14-18:50:12 [yas] Prepared just-in-time loading of snippets successfully.
2017-02-14-18:50:40 M-] is undefined
2017-02-14-18:50:41 CHILDREN [2 times]
2017-02-14-18:50:00 ‘show-all’ is an obsolete command (as of 25.1); use ‘outline-show-all’ instead.
2017-02-14-18:50:01 Invalid face reference: nil [33 times]
2017-02-14-18:51:01 Auto-saving...done
2017-02-14-18:51:03 Saving file /Users/gsl/lisp.d/init.el...
2017-02-14-18:51:06 Wrote /Users/gsl/lisp.d/init.el
2017-02-14-18:51:09 mwheel-scroll: Beginning of buffer [5 times]
2017-02-14-18:51:11 Mark set
2017-02-14-18:51:21 previous-line: Beginning of buffer [10 times]

I searched on EmacsWiki, Reddit and emacs.sx of course, to no avail.

I am aware of command-log-mode, which can be adjusted to log with timestamps, but it is useful only for interactive commands, not all messages, including Emacs' "system" ones.

Instead, every message logged to the Messages buffer should be timestamped.

How can one add a timestamp to each entry in Emacs' Messages buffer, no matter its source?

gsl
  • 1,742
  • 17
  • 34
  • 2
    This sounds like a feature request for Emacs. The `message` command is implemented in C and likely has direct callers, so you won't be able to ensure every logged message gets a timestamp without building Emacs yourself. That said, you may be able to advise the `message` command to introduce a time stamp when it is called from Elisp. Some caution is required: `message` can be called with no args, an empty format string, etc. You also want to avoid a recursive loop should your timestamp advice itself call `message` in some code path. – glucas Apr 14 '17 at 18:33
  • 1
    I have not tried it but it seems like you should be able to advice onto message https://www.emacswiki.org/emacs/AdvisingFunctions http://stackoverflow.com/questions/21524488/how-to-redirect-message-echo-output-to-a-buffer-in-emacs https://superuser.com/questions/669701/emacs-disable-some-minibuffer-messages – eflanigan00 Apr 14 '17 at 21:29
  • 1
    I'd be inclined to use `after-change-functions` (in the messages buffer) to implement that. Whenever something is inserted at the end of the buffer, prefix a timestamp to it. – phils Jun 14 '17 at 09:41
  • 2
    @phils Refer from https://www.gnu.org/software/emacs/manual/html_node/elisp/Change-Hooks.html Output of messages into the *Messages* buffer does not call these functions, and neither do certain internal buffer changes, such as changes in buffers created by Emacs internally for certain jobs, that should not be visible to Lisp programs. – xinfa tang Mar 02 '18 at 02:48

4 Answers4

11

I have the following snippet in my init.el, which was adapted from an original I found in the following Reddit thread: http://www.reddit.com/r/emacs/comments/16tzu9/anyone_know_of_a_reasonable_way_to_timestamp/

(EDIT: modernised to advice-add and removed clumsy read-only buffer handling on advice of @blujay)

(defun sh/current-time-microseconds ()
  "Return the current time formatted to include microseconds."
  (let* ((nowtime (current-time))
         (now-ms (nth 2 nowtime)))
    (concat (format-time-string "[%Y-%m-%dT%T" nowtime) (format ".%d]" now-ms))))

(defun sh/ad-timestamp-message (FORMAT-STRING &rest args)
  "Advice to run before `message' that prepends a timestamp to each message.

Activate this advice with:
(advice-add 'message :before 'sh/ad-timestamp-message)"
  (unless (string-equal FORMAT-STRING "%s%s")
    (let ((deactivate-mark nil)
          (inhibit-read-only t))
      (with-current-buffer "*Messages*"
        (goto-char (point-max))
        (if (not (bolp))
          (newline))
        (insert (sh/current-time-microseconds) " ")))))

(advice-add 'message :before 'sh/ad-timestamp-message)

This results in decoration of the *Messages* buffer as follows:

[2017-06-13T07:21:13.270070] Turning on magit-auto-revert-mode...
[2017-06-13T07:21:13.467317] Turning on magit-auto-revert-mode...done
[2017-06-13T07:21:13.557918] For information about GNU Emacs and the GNU system, type C-h C-a.
Stuart Hickinbottom
  • 2,343
  • 14
  • 16
  • 3
    I wonder why this isn't provided as an option by default. – bertfred Jun 14 '17 at 12:04
  • 1
    Brilliant, this is exactly what I was looking for. Thank you. – gsl Jun 14 '17 at 14:15
  • 3
    @bertfred Because no one has made it happen. Perhaps, that's you? – Phil Lord Jun 15 '17 at 19:30
  • 3
    Could you rewrite the advice using `advice-add`? It's the preferred method now, as it knows how to handle situations that `defadvice` can't. Also, you should probably not do `(read-only-mode 0)`, because that is probably permanent. You can bind `inhibit-read-only` to `t` around the code that modifies the buffer. –  Aug 06 '17 at 06:10
  • 3
    I use your code, but display many messages just a timestamp – xinfa tang Feb 01 '18 at 03:27
  • 1
    @Stuart Hickinbottom I think it's because the builtin message function do some magic, such as ignore empty message, show "[N times]" instead if duplicated message found, you can simply avoid add timestamp to empty message – xinfa tang Mar 02 '18 at 03:30
  • 1
    No, it's not because of blank messages. I just tried this, and it consistently drops first message from eglot: "[eglot] Waiting in background for server [...]". The message from "[eglot] Connected [...]" message is fine though. This is emacs 27, if that matters. – AFoglia Sep 16 '20 at 00:26
8

The translation of @xinfatang's simple solution to the new advice-add syntax as a wrapper around the message function is:

(defun my-message-with-timestamp (old-func fmt-string &rest args)
   "Prepend current timestamp (with microsecond precision) to a message"
   (apply old-func
          (concat (format-time-string "[%F %T.%3N %Z] ")
                   fmt-string)
          args))

Outputs *Messages* like:

[2018-02-25 10:13:45.442 PST] Mark set

To add:

 (advice-add 'message :around #'my-message-with-timestamp)

To remove:

 (advice-remove 'message #'my-message-with-timestamp)
mithos
  • 81
  • 1
  • 1
  • 3
    You could also just filter the args, rather than using around advice: `(advice-add 'message :filter-args 'with-timestamp)` would work with a function like this: `(defun with-timestamp (args) (push (concat (format-time-string "[%F %T.%3N] ") (car args)) (cdr args)))` – glucas Feb 25 '18 at 19:50
  • 2
    @glucas Nice! I get timestamps w/o message though when I hover the mouse over the minibuffer. Is there a way to avoid that? – AstroFloyd Dec 23 '19 at 19:59
4

Refer to https://www.emacswiki.org/emacs/DebugMessages:

        (defadvice message (before when-was-that activate)
          "Add timestamps to `message' output."
          (ad-set-arg 0 (concat (format-time-string "[%Y-%m-%d %T %Z] ") 
                                (ad-get-arg 0)) ))

Finally, I still like Stuart Hickinbottom 's answer, because it avoids showing timestamp in the minibuffer. The following is a modified version which I use, it ignores messages only shown in the echo area(by letting message-log-max to nil before message function call):

    (defun my/ad-timestamp-message (FORMAT-STRING &rest args)
      "Advice to run before `message' that prepends a timestamp to each message.
        Activate this advice with:
          (advice-add 'message :before 'my/ad-timestamp-message)
        Deactivate this advice with:
          (advice-remove 'message 'my/ad-timestamp-message)"
      (if message-log-max
          (let ((deactivate-mark nil)
                (inhibit-read-only t))
            (with-current-buffer "*Messages*"
              (goto-char (point-max))
              (if (not (bolp))
                  (newline))
              (insert (format-time-string "[%F %T.%3N] "))))))
     (advice-add 'message :before 'my/ad-timestamp-message)
NickD
  • 27,023
  • 3
  • 23
  • 42
xinfa tang
  • 151
  • 4
1

My solution expands on Stuart Hickinbottom 's and xinfa tang 's answers by NOT printing the timestamp of repeated messages:

(defvar my-package--last-message nil
  "Last message with timestamp appended to it.")

(defun my-package-ad-timestamp-message (format-string &rest args)
  "Prepend timestamp to each message in message buffer.

FORMAT-STRING and ARGS are used by `message' to print a formatted string.

Enable with (add-hook 'find-file-hook 'my-package-ad-timestamp-message)"
  (when (and message-log-max
             (not (string-equal format-string "%s%s")))
    (let ((formatted-message-string (if args
                                        (apply 'format `(,format-string ,@args))
                                      format-string)))
      (unless (string= formatted-message-string my-package--last-message)
        (setq my-package--last-message formatted-message-string)
        (let ((deactivate-mark nil)
              (inhibit-read-only t))
          (with-current-buffer "*Messages*"
            (goto-char (point-max))
            (when (not (bolp))
              (newline))
            (insert (format-time-string "[%F %T.%3N] "))))))))

It accomplishes this by comparing the current message to the last message printed with a timestamp.

coffeepenbit
  • 81
  • 3
  • Thanks, very useful to have the option not to print timestamps of repeated messages. – gsl Apr 24 '21 at 12:09