Get current function name in common lisp

Question

I know this is beyond the standard, but is there an official way to get the current function name, in a specific implementation, say SBCL? Sometimes I want to put the current function name in log messages. I believe if there is a consistent way to get the current function name, it makes maintaining the codes easier, at least I don't have to change the log message every time when I change the function name.

Currently I am using a wrapper macro around the defun

(defmacro defun2 (name (&rest args) &body body)
  `(defun ,name (,@args)
     (let ((fun-name ',name))
       ,@body)))

(defun2 foo (x y)
  (format nil "fun ~a: x is ~a, y is ~a~%"
          fun-name x y))

But I am interested to know if there is any easier way.

Answer 1

The hard way

Say you want to add logging to your application, so you define your own little macros and functions, like you would do in another language:

(defpackage :logging (:use :cl))
(in-package :logging)

In order to be able to turn off logging, or to change your implementation as you want, you decide that logging is better encapsulated as a macro:

(defmacro note (&rest things)
  `(note% (first (sb-debug:list-backtrace :count 1))
          (list ,@things)))

Here above, I'm using sb-debug:list-backtrace to capture the current stack frame. It is not portable and when your function is inline you won't see its name but the name of the caller. But that's an acceptable compromise that every logging library accept in most languages.

Then, you are free to implement that as you want, for example with the condition system:

(define-condition note (simple-warning)
  ((timestamp
    :initarg :timestamp
    :reader note-timestamp)
   (origin
    :initarg :origin
    :reader note-origin)
   (data
    :initarg :data
    :reader note-data))
  (:report (lambda (c s)
             (format s
                     "~d ~a ~@<~s~:>"
                     (note-timestamp c)
                     (note-origin c)
                     (note-data c)))))

The note% function here warns, but the idea is that at a higher level you capture all those conditions and write them somewhere else. In case there is no handler, SBCL will print it on the REPL so that's fine too:

(defun note% (origin data)
  (warn 'note
        :timestamp (local-time:now)
        :origin origin
        :data data))

Finally, you can test that as follows:

(defun test (in)
  (flet ((y (x) (note :x x)))
    (note :before :in in)
    (y 6)
    (note :after)))

For example:

(test 15)
WARNING: 2022-10-19T15:17:05.297198Z (TEST 15) (:BEFORE :IN 15)
WARNING: 2022-10-19T15:17:05.297603Z ((FLET Y IN TEST) 6) (:X 6)
WARNING: 2022-10-19T15:17:05.297706Z (TEST 15) (:AFTER)

The easy way

Instead of doing all the above, you may want to activate tracing when giving your code to your users. You select the functions you want to trace, and redirect *TRACE-OUTPUT* to your logs (or use a custom report function, see below).

The SBCL implementation assumes that string arguments denote packages, but that's not portable. However this unportability has less impact as it is only done in one place and does not touch all the code. It is always possible to list all symbols and trace them explicitly if you want, or use reader macros to call the implementation-specific TRACE in a way that suits you.

For example, using SBCL, let's trace all the symbols in my newly created package:

(trace "LOGGING")

And run the same test:

(test 15)
  0: (LOGGING::TEST 15)
    1: (LOGGING::NOTE% (LOGGING::TEST 15) (:BEFORE :IN 15))
      2: (LOGGING::NOTE-TIMESTAMP #<LOGGING::NOTE {100EC7CC33}>)
      2: NOTE-TIMESTAMP returned @2022-10-19T15:22:05.315488Z
      2: (LOGGING::NOTE-ORIGIN #<LOGGING::NOTE {100EC7CC33}>)
      2: NOTE-ORIGIN returned (TEST 15)
      2: (LOGGING::NOTE-DATA #<LOGGING::NOTE {100EC7CC33}>)
      2: NOTE-DATA returned (:BEFORE :IN 15)
WARNING: 2022-10-19T15:22:05.315488Z (TEST 15) (:BEFORE :IN 15)
    1: NOTE% returned NIL
    1: (LOGGING::NOTE% ((FLET LOGGING::Y :IN LOGGING::TEST) 6) (:X 6))
      2: (LOGGING::NOTE-TIMESTAMP #<LOGGING::NOTE {100EC9DBB3}>)
      2: NOTE-TIMESTAMP returned @2022-10-19T15:22:05.319801Z
      2: (LOGGING::NOTE-ORIGIN #<LOGGING::NOTE {100EC9DBB3}>)
      2: NOTE-ORIGIN returned ((FLET Y :IN TEST) 6)
      2: (LOGGING::NOTE-DATA #<LOGGING::NOTE {100EC9DBB3}>)
      2: NOTE-DATA returned (:X 6)
WARNING: 2022-10-19T15:22:05.319801Z ((FLET Y IN TEST) 6) (:X 6)
    1: NOTE% returned NIL
    1: (LOGGING::NOTE% (LOGGING::TEST 15) (:AFTER))
      2: (LOGGING::NOTE-TIMESTAMP #<LOGGING::NOTE {100ECAE773}>)
      2: NOTE-TIMESTAMP returned @2022-10-19T15:22:05.323732Z
      2: (LOGGING::NOTE-ORIGIN #<LOGGING::NOTE {100ECAE773}>)
      2: NOTE-ORIGIN returned (TEST 15)
      2: (LOGGING::NOTE-DATA #<LOGGING::NOTE {100ECAE773}>)
      2: NOTE-DATA returned (:AFTER)
WARNING: 2022-10-19T15:22:05.323732Z (TEST 15) (:AFTER)
    1: NOTE% returned NIL
  0: TEST returned NIL

Without changing the code, I now can see exactly what is happening. In fact I do not need to implement logging functions at all.

Some implementations allows you to configure how tracing is being done, so if you want to add timestamps you should be able to do so too. In SBCL, this is the :report option which accepts a function name. Here I'm intercepting each entry using a custom my-report function:

(trace "LOGGING" :report my-report)

(defun my-report (&rest args)
  (fresh-line *trace-output*)
  (print (list* (local-time:now) args) *trace-output*))

For example:

(test 15)
(@2022-10-19T15:34:58.543114Z 0 LOGGING::TEST :ENTER #<SB-DI::COMPILED-FRAME SB-INT:SIMPLE-EVAL-IN-LEXENV> (15)) 

(@2022-10-19T15:34:58.552193Z 1 LOGGING::NOTE% :ENTER #<SB-DI::COMPILED-FRAME LOGGING::TEST> ((LOGGING::TEST 15) (:BEFORE :IN 15))) 

(@2022-10-19T15:34:58.552359Z 2 LOGGING::NOTE-TIMESTAMP :ENTER #<SB-DI::COMPILED-FRAME (SB-KERNEL::CONDITION-REPORT LOGGING::NOTE)> (#<LOGGING::NOTE {100F5E7F23}>)) 

(@2022-10-19T15:34:58.552461Z 2 NOTE-TIMESTAMP :EXIT
 #<SB-DI::COMPILED-FRAME (SB-KERNEL::CONDITION-REPORT NOTE)>
 (@2022-10-19T15:34:58.552306Z)) 
....