7max / log4cl

Common Lisp logging framework, modeled after Log4J

Introduction

NOTE - Because of some mishap with QuickLisp, June 2013 QuickLisp distribution pulled the master branch of Log4CL instead of stable branch as intended.

Very few incompatibilities been reported, and it makes no sense to downgrade version that been already available in QuickLisp, therefore QuickLisp will continue to pull the master branch from now on.

The major difference of Log4CL 1.1.x version from 1.0.x is the Emacs/Slime integration module, called Log4Slime. This document is written with assumption that you will have Log4Slime loaded and enabled in Emacs.

Installation

Log4CL is available from QuickLisp. To load it use (ql:quickload :log4cl) command from REPL. Log4Slime is available in QuickLisp since June 2013.

Enabling Log4Slime

(ql:quickload :log4slime)
(log4slime:install)

You should get a message like this:

Wrote ~/quicklisp/log4slime-setup.el

Add the following two statements to your ~/.emacs file
------------------------------------------------------
(load "~/quicklisp/log4slime-setup.el")
(global-log4slime-mode 1)
------------------------------------------------------

Follow the above instructions. The most likely point of failure here may be log4slime.el trying to poke the Lisp side to see if log4slime is loaded, and that for some reason it fails.

If it fails, there should be a message in *Messages* buffer, that looks like this: Unable to load log4slime lisp support: <lisp side condition>

In case you did get the above message and you think you fixed the cause, you can make log4slime try again, by turning M-x global-log4slime-mode off/on a few times

You can verify if log4slime is enabled, by looking for the Log4CL menu on top menubar in REPL and Lisp mode buffers, or by submitting a log statement from REPL and seeing output colorized.

Hello world

(progn
  (log:info "I just ate a ~5f, feeling tired" pi) 
  (when (log:debug)
    (dotimes (sheep 3)
      (log:debug sheep "zzz")))
  (log:warn "doh fell asleep for" (random 10) "minutes"))

Should produce the following output

You can notice several things right away.

• You can intermix strings and expressions, and expressions will be printed as their un-evaluated form as well as the their value; using a constant FORMAT control string as first argument automatically switches to FORMAT mode.

• Log statements without arguments, turn into conditional expression that tells you if logging is enabled or not

• The log output contains some headers in addition to the raw log message, such as the log level that message was submitted with, the time of the message as well as what looks like the name of the current package, and (If you have Log4Slime loaded and turned on), these headers use different faces from actual log message.

Changing the log level

You can change the log level with by doing (log:config :debug) from REPL. Alternatively, with Log4Slime enabled in REPL buffer, you can right-click on the cl-user part and change the log level from a popup menu.

There is a slight difference between doing it using above two methods, with log:config command, the level is changed for the ROOT category, but right clicking on the package name, changes the log level only for that package.

To change the ROOT category from Emacs, you can use Log4CL dropdown submenu, or Emacs command log4slime-level-selection which is bound to C-c C-g by default.

After pressing C-c C-g which invokes the log4slime-level-selection command you get the following window.

Pressing "p" to select the package category shows effective log level and allows you to change like so

This concludes the very basic introduction, if you were confused by what various terms such as "category" mean, click on the hyperlink to read more about Log4CL concepts.

Or you can skip the theory and just continue to learn by example.

Automatic category naming

Try putting the from the previous section into a DEFUN instead of a PROGN form like so:

(defun hello ()
  (log:info "I just ate a ~5f, feeling tired" pi) 
  (when (log:debug)
    (dotimes (sheep 3)
      (log:debug sheep "zzz")))
  (log:warn "doh fell asleep for" (random 10) "minutes"))

If you run it now, the output under both SBCL and CCL should look like this.

Right click on the blue function name, allows you to change the log level for that specific function.

That is because Log4CL logging macros, automatically determine the category for logging, based on the context where log statement appears. In above example the function was defined in the package CL-USER and function name was HELLO, so the target category of any logging inside the function, was automatically CL-USER.HELLO

It starts with the package, then function. You can try putting one of the log statements inside of a LABELS or FLET forms, to see what happens.

Also note the farthest to the right in the logging category name, the more specific. The level for "hello" overrides that for "cl-user", which in turn overrides that of the root category.

Naming in source files

For the next few examples, it is recommended that you load the examples come together with Log4CL, by doing (ql:quickload :log4cl-examples)

It should produce the following output:

One thing you should notice, is that source file where function is defined now appears as part of the log message too. Go to the source of "greetings". Before you try to use Slime's famous M-. shortcut, try clicking on blue "greetings" word with a left mouse button.

If everything went better then expected, it should land you at the first log statement of the (defun greetings ()). Cool eh?

Naming in CLOS methods

Quickly browse through naming-examples.lisp. There are a few methods defined, including :after/:around methods, as well as some with EQL specializers.

Run a few of them from REPL, like so:

Log statements inside of methods, are using the category name of the generic function, extended with qualifier, and all non-T specializers.

Try going to the source of the above methods by clicking on them. It should land in the right method, without showing Slime's XREF window.

Note how by changing the level of the foobar you control all the methods, but can override them based on their specializers. Try setting :after category to different levels, to control all the :after methods together.

In addition to playing with methods, try (setf (test.package.one:greetings) "Hey") too.

Context sensitivity

As you browse through source, and are inside of one of the methods, check out the Log4CL dropdown menu. Note that "Defun" submenu changes for each method.

Keyboard level selection

Also try C-c C-g shortcut in the same place. You can configure it not to show the selection window at all, by customizing the log4slime-level-selection-single-key Emacs variable.

After pressing C-c C-g while inside of the method

You can change keys for the selecting various levels by doing M-x customize-group RET log4slime RET

Note that keyboard selection ignores the Control key so C-c C-g p u is same as C-c C-g C-p C-u

Resetting the mess

If you had forgotten which levels you set for what, and just want to see which levels are set where.

You can display current logging configuration by doing (log:config) without any arguments, it willdisplay a tree

If you have had set a lot of custom levels, and now need to get rid of them, "Reset Children" menu item will nukes the log level from everything underneath the parent. Doing "Reset Children" on the ROOT category, gets rid of every other log level that was set anywhere. Keyboard equivalent is C-c C-g r

Logging configurations

After setting the log levels of a few methods, try doing (log:save :foo) then messing around.. You can restore the named configuration with (log:restore :foo). Configurations are saved in a file in the home directory, so they survive image restarts

See the Finding needle in a haystack section.

The magic of (LOG:CONFIG)

Section To be written, for now simply see docstring for LOG:CONFIG

Read the docstring and play with options, below are a few examples:

Pattern Layout

Section to be written, for now see docstring for docstring for PATTERN-LAYOUT

Common Practices

Some common recipes.

Log levels for production

Generally log levels INFO and below, are used in normal operations of software, while levels higher then INFO are used by programmers.

• FATAL is used for un-recoverable errors, that require restart of an application or major component, the FATAL messages are to inform the user that something had died in a way that should not normally happen.

• ERROR is for serious but generally recoverable errors, that occur doing a normal operation of software. File not found, or such.

• WARN is for "suspicious" things, or to inform the user that some automatic corrective action had failed. Maximum number of retries reached or such.

• INFO is for informing on major steps that software is performing, and is usually thought of the maximum log level used in normal operations, its "Say what you are doing but don't flood" type of messages.

By default Log4CL is configured with root category having INFO log level.

Log levels for development

DEBUG is for for informing about detailed steps taken by operations and printing intermediate values.

TRACE is for very detailed debugging, like printing variables inside loops and such.

DEBU1..DEBU9 log levels are numerically around the TRACE and can be used if you need more granularity. One possibility is that (log:expr) macro, can be configured via LOG:PACKAGE-OPTIONS mechanism, to use different log level then DEBUG and can set to use one of the extra levels.

OFF log level is very important counter-part for DEBUG and TRACE. Its used for "narrowing things down in reverse", which is described in the next section

Finding needle in a haystack

Programmers often need to concentrate on a specific area of their software. With traditional non-hierarchical logging system, having a lot of debug sprinkled around the code, flood the programmers with a lot of information they don't need, and makes it hard to find the messages relevant to the problem being debugged.

Because Log4CL is hierarchical, its easy to narrow down the logging, to focus on exactly the right area, by using the following process.

1. Turn DEBUG on for the root category, or entire package and then run your code through the functionality that you are focusing on. REPL will fill with a lot of debugging output.

2. Right-click on each message that is not related to a problem, and turn the corresponding category OFF. You can how go wide or narrow, turn off entire packages or source files, or by individual methods, functions or local functions. If you went too far, use Reset children command on the parent category.

   If you use CLOS, use the category hierarchy to your advantage, if for example you think problem relates to before or after method, you can can control logging for all :AFTER methods of generic function by clicking :after category in (<gf name> :after <specializer> ...)

3. Once you narrowed down the logging to your liking, you can quickly save that configuration of log levels with (LOG:SAVE), and later (may be in a different image, or even different machine) restore it with (LOG:RESTORE), and you can give these saved configuration names, such as (LOG:SAVE :bug-123)

Glossary

Very small glossary of Log4CL concepts

Loggers and categories

Loggers are named singleton objects that form a hierarchy, and are sources of log messages, or more correctly entry points where log message enter the logging system. Each call to a logging macro like (log:debug ...) operates on a specific logger object (See also naming section).

Logger's unique name is called "logger's category", or "category name". Loggers form a hierarchy, based on their category names, where child loggers have their category name prefixed by that of the parent, followed by a dot. So if we have loggers A, A.B, A.B.C and A.B.D then logger A is parent of A.B, which has two children A.B.C and A.B.D - as shown on below diagram. (Note: ROOT logger category name is empty string)

ROOT---A---A.B---A.B.C
             |
             \---A.B.D

Because loggers are singletons, logger category name is usually shortened to just CATEGORY and is used inter-changeably with the word LOGGER; the convention is that thing is "a logger" when talking about actual Lisp object, and "category" otherwise.

Each logger can have a log level threshold, or if its does not have one, it inherits one from its parent. To ensure that for any logger, an effective log level can be determined, the ROOT logger always have a level.

Loggers will only pass through messages, if logger's threshold level is equal or greater verbosity, then log message. For example if in above example logger A is configured with info log level, then (log:warn ...) and (log:info) messages will be passed through, but (log:debug) messages would not.

Appenders

Appenders process log messages by writing them to files, or displaying them on the screen. Appenders attach to a specific logger, and each logger can have many appenders attached.

When a log message passes through a logger that has appenders, they are all called in turn to do appender specific processing, be it writing log message to a file, or a terminal. After all of logger's appenders had processed the message, its passed on to the parent logger.

So log messages inheritance flows in reverse order from the log level one, tricking up from child loggers towards root, with below exception.

Each logger has a property called additivity, which is T by default, which controls the above process. When additivity is NIL, logger is called non-additive and any messages that reach it, will not be passed to the parents.

Usually only root logger, or non non-additive loggers will have any appenders attached to them.

Layouts

When appender decide they want to process the log message, they format the log message by means of a layout. Layout is a separate object, that attaches to each appender, and is responsible for the textual formatting of the message.

So while appender provides and manages any serialization for the stream to write to, the layout is actually formatting the log message into that stream.

Log4CL provides two layouts, SIMPLE-LAYOUT which is well, simple, and a very configurable PATTERN-LAYOUT, which specifies the formatting of log messages by mean of printf/format like control string.

Easiest way to use the pattern layout, is by using LOG:CONFIG command to select between several predefined formats.

Or you can look for list of all supported format documentation for the PATTERN-LAYOUT class. Please note that if you are drafting your own format, that Log4SLime fontification relies on regular expressions and the log messages being in a certain order. If your layout is not a minor modification of an built-in one, the Log4Slime fontification may stop working. You can of course adjust the regular expressions used by Log4Slime to match your own custom layout to compensate.

Log Levels

In Log4CL log levels are numeric constants, in order of increased verbosity:

• Turn off logging 0=OFF

• Standard log levels 1=FATAL, 2=ERROR, 3=WARN, 4=INFO, 5=DEBUG

• Extra debug levels 6..9 named DEBU1 through DEBU4

• Standard log level 10=TRACE

• Extra debug level 11..15 named DEBU5 through DEBU9

Effective log level

Effective log level of the logger X is determined as follows.

1. If logger has level threshold set, then this level is the effective log level.

2. If logger is not first child of a parent, whose category is same as the package name logger was instantiated from, the effective log level of X is the effective log level of its parent logger.

3. If logger is first child of a parent P named same as package, and there exists a sibling logger S, with the last part of category name equal to that of a source file logger X was instantiated from, and S has a level threshold set, that level is effective level of logger X

4. Otherwise effective level of logger X is effective level of its parent.

ROOT logger always has a level threshold set, so above steps always result in a valid log level.

Effective log level is returned by the function (log4cl:effective-log-level LOGGER)

FAQ

I don't see log messages from other threads.

The *TERMINAL-IO* value bound in the other threads is probably different and points
to other place (likely *inferior-lisp* buffer under Slime)

1. (log:config :sane2) will copy messages from other threads to REPL while continuing output to thread specific *TERMINAL-IO* (REPL thread will still only log to REPL)

2. (log:config :sane :this-console) will redirect all logging to current console regardless of thread local values of *TERMINAL-IO*

Why Log4CL starts its own thread, and how I get rid of it

Its a flusher thread to flush the appenders, it increases performance greatly when there is a lot of logging.oe

You can stop it by calling (log4cl:stop-hierarchy-watcher-thread)

On SBCL Log4CL uses *EXIT-HOOKS* and *SAVE-HOOKS* to automatically flush all appenders on exit, so that last second of logging is not lost, and to terminate the watcher thread when saving image, which can't be done with multiple threads running.

I'd like just the log messages, and not all the extra stuff

Use pattern layout with just %m%n format (message + newline)

How do I log into a file

(log:config :daily "file.txt") which will be backed up each day to file.txt.YYYYMMDD

I want both log file and backup log file to have YYYYMMDD prefix or roll once per week

(log:config :daily "file.txt.%Y%m%d") file will roll when %Y%m%d expansion changes.

What about just one plain file, without rolling

(log:config :daily "file.txt" :backup nil)

log4cl's Issues

log expansion should not capture stream

(let ((stream 123)) (log:info stream)) does not work as expected.

Output:
<INFO> [17:25:02] cl-user () - STREAM: #<SB-PRETTY:PRETTY-STREAM {BCDFF21}>

log4cl not detecting existing package name

I'm getting this when doing

(defpackage :turtl
  ...)
(in-package :turtl)
(log:config '(turtl) :debu1)

Gives me:

Logger named #1=(TURTL) not found. If you want to create it, use (LOG:CONFIG (LOG:LOGGER #1#) ...) instead

Oddly enough, if I change the load order in the .asd to make the (log:config '(turtl) :debu1) later, it works. Is this possibly some kind of race condition between the package being declared and the log:config call?

Thanks for the great library. I'm using it in all my new projects.

Another README typo

Search for " theh system"

Sly integration

Hey! I love this software, it really changed my logging life!
Recently I switched to Sly from Slime and I am struggling to get the interactive features and colorization working. Does any body know if someone already approached this, or if not any suggestions for me to start a contribution like 'log4sly'?

Thanks in advance

minor issues with emacs support

The emacs support is delightful!

In this example...

cl-user> (log:info '(x y z) "yogurt for breakfast!")
 <INFO> [08:51:06]  (x y z) - yogurt for breakfast!
; No value
cl-user> 

It seems to think yogurt is a function, but you and I know it's a dairy product.

Further, if you place the cursor on the close paren, well between the "z" and ")" and then bring up the context menu you get an ecase error. Yeah, ecase!

JOIN-THREAD-ERROR

What is going on here?

$ sbcl

* (ql:quickload "log4cl" :silent t)
* (log4cl:start-hierarchy-watcher-thread)
* (LOG4CL-IMPL::SAVE-HOOK)
ERROR - Caught SB-THREAD:JOIN-THREAD-ERROR during
        '(LOG4CL-IMPL:STOP-HIERARCHY-WATCHER-THREAD :JOIN-THREAD):
        Joining thread failed: thread #<THREAD "Hierarchy Watcher" ABORTED

                                        {10054D0CE3}> did not return normally.;
        Continuing.

Log4Slime Elisp side fails to detect numeric EQL specializer

When point is inside of a method like (defmethod blah ((a a-type) (b (eql 42)) the Log4CL menubar and C-c C-g d show category as blah a-type. It should be blah a-type 42

Troubles with log4slime

When I add log4slime to my emacs config, I have the following problems:

When I start slime I get a bunch of errors:

WARNING: SWANK-LOADER also exports the following symbols:
  (SWANK-LOADER:*FASL-DIRECTORY* SWANK-LOADER:DUMP-IMAGE SWANK-LOADER:INIT SWANK-LOADER:*SOURCE-DIRECTORY*)
See also:
  The ANSI Standard, Macro DEFPACKAGE
  The SBCL Manual, Variable SB-EXT:*ON-PACKAGE-VARIANCE*
STYLE-WARNING: redefining SWANK-LOADER::Q in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::LISP-VERSION-STRING in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::UNIQUE-DIR-NAME in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::FILE-NEWER-P in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::SLIME-VERSION-STRING in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::DEFAULT-FASL-DIR in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::BINARY-PATHNAME in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::HANDLE-SWANK-LOAD-ERROR in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::COMPILE-FILES in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::LOAD-USER-INIT-FILE in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::LOAD-SITE-INIT-FILE in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::SRC-FILES in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::APPEND-DIR in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::CONTRIB-DIR in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::LOAD-SWANK in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::DELETE-STALE-CONTRIB-FASL-FILES in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::COMPILE-CONTRIBS in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::LOADUP in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::SETUP in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::STRING-STARTS-WITH in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::LIST-SWANK-PACKAGES in DEFUN
STYLE-WARNING: redefining SWANK-LOADER::DELETE-PACKAGES in DEFUN
STYLE-WARNING: redefining SWANK-LOADER:INIT in DEFUN
STYLE-WARNING: redefining SWANK-LOADER:DUMP-IMAGE in DEFUN
WARNING: Not reloading SWANK.  Package already exists.

And I don't get any syntax highlighting/fontification.

Does the load command need to be in a specific place in my emacs configuration?

Implement Emacs side filtering of existing REPL log messages

It would be nice if in addition to controlling the log level of future logging, there was ability to hide and unhide log messages that are already in REPL

Interface could be right-click -> together with log levels, a new choice "Hide".

This needs thought, because if user selects "Hide" new messages from same place would appear in the future. Should these messages still appear? If so, then we have to maintain visibility flag per message in REPL, rather then using invisibility-spec, which may lead to performance problem

And where would "Unhide" go, "Reset children" will also unhide is one option.

Another minimalist solution is simply have "Off+Delete" choice next to "Off", which turns logging off for that category, and permanently erases any existing messages in REPL

Recursive lock attempt with `log4cl`

CL-USER> (defun x () (log:info "foo"))
X
CL-USER> (defun y () (log:info "bar ~A" (x)))
Y
CL-USER> (log:config :info)
; No value
CL-USER> (y)
Recursive lock attempt #<SB-THREAD:MUTEX "Anonymous lock" owner: #<SB-THREAD:THREAD "repl-thread" RUNNING {100AC7FFA3}>>.
   [Condition of type SIMPLE-ERROR]

Restarts:
 0: [RETRY] Retry SLIME REPL evaluation request.
 1: [*ABORT] Return to SLIME's top level.
 2: [ABORT] abort thread (#<THREAD "repl-thread" RUNNING {100AC7FFA3}>)

Backtrace:
  0: (SB-THREAD::%TRY-MUTEX #<unavailable argument> #<unavailable argument>)
  1: (SB-THREAD:GRAB-MUTEX #<SB-THREAD:MUTEX "Anonymous lock" owner: #<SB-THREAD:THREAD "repl-thread" RUNNING {100AC7FFA3}>> :WAITP T :TIMEOUT NIL)
  2: ((FLET "WITHOUT-INTERRUPTS-BODY-1" :IN SB-THREAD::CALL-WITH-MUTEX))
  3: (SB-THREAD::CALL-WITH-MUTEX #<CLOSURE (FLET SB-THREAD::WITH-MUTEX-THUNK :IN LOG4CL-IMPL:APPENDER-DO-APPEND) {7FFF87B5CE8B}> #<SB-THREAD:MUTEX "Anonymous lock" owner: #<SB-THREAD:THREAD "repl-thread" R..
  4: ((:METHOD LOG4CL-IMPL:APPENDER-DO-APPEND :AROUND (LOG4CL-IMPL:SERIALIZED-APPENDER T T T)) #<LOG4CL-IMPL:CONSOLE-APPENDER {100C522BC3}> #<LOG4CL-IMPL::FILE-LOGGER CL-USER.X NIL {100F60B983}> 4 #<FUNCTI..
  5: ((LABELS LOG4CL-IMPL::LOG-TO-LOGGER-APPENDERS :IN LOG4CL-IMPL::LOG-WITH-LOGGER) #<LOGGER +ROOT+ {100BAA2E83}> #<LOG4CL-IMPL::FILE-LOGGER CL-USER.X NIL {100F60B983}> 4 #<FUNCTION (FLET "log-stmt16" :IN..
  6: ((LABELS LOG4CL-IMPL::LOG-TO-LOGGER-APPENDERS :IN LOG4CL-IMPL::LOG-WITH-LOGGER) #<LOG4CL-IMPL::FILE-LOGGER CL-USER NIL {100F60B083}> #<LOG4CL-IMPL::FILE-LOGGER CL-USER.X NIL {100F60B983}> 4 #<FUNCTION..
  7: ((LABELS LOG4CL-IMPL::LOG-TO-LOGGER-APPENDERS :IN LOG4CL-IMPL::LOG-WITH-LOGGER) #<LOG4CL-IMPL::FILE-LOGGER CL-USER.X NIL {100F60B983}> #<LOG4CL-IMPL::FILE-LOGGER CL-USER.X NIL {100F60B983}> 4 #<FUNCTI..
  8: (LOG4CL-IMPL::LOG-WITH-LOGGER #<LOG4CL-IMPL::FILE-LOGGER CL-USER.X NIL {100F60B983}> 4 #<FUNCTION (FLET "log-stmt16" :IN X) {100EF48F7B}> #<PACKAGE "COMMON-LISP-USER">)
  9: (X)```

As logging is used in more and more complex systems, this sometimes led to terrible (and unexpected) crashes.

Left click does not work non-interned method name

Issue, if you do not use some package, but put a method on a generic function in it like so:

(in-package :some-package)
(defmethod asdf:operate (....)
   (log:info "blah"))

Then message will come out as

<INFO> [time] some-package (operate ...) - blah

And going to the left click go to source fails, because it there is no (FIND-SYMBOL "OPERATE") in some-package

Solution would be to change naming to use prin1 for symbols instead of princ,
this would change automatic naming to produce some-package.asdf:operate as the logger name, and message will be

<INFO> [time] some-package (asdf:operate ...) - blah

Log4slime Error Upon Startup (org-compatible-face)

I installed log4cl and log4slime through Quicklisp and executed the install command.
After adding the requested lines to my .emacs file, I get the following error on Emacs launch:

Symbol's function definition is void: org-compatible-face

I'm usually running Emacs on my terminal, but even if I start it in X mode, the error still occurs. The Emacs version is
GNU Emacs 24.3.1 (x86_64-unknown-linux-gnu, GTK+ Version 3.8.1) of 2013-04-29 on eric
and the log4slime version from Quicklisp is
#<SYSTEM log4slime / log4cl-stable-26f358ee-git / quicklisp 2013-06-15>

If there's any additional information on my setup that you need, I'd be happy to provide you with what I can.

slime error message when loading log4cl

I use the these entries in my .emacs file for emacs 23.4.1:

(load "~/quicklisp/log4slime-setup.el")
(global-log4slime-mode 1)

and I get these two error messages in the messages buffer of emacs/slime:

error in process filter: ad-Orig-slime-repl-emit: Text is read-only
error in process filter: Text is read-only

The two error messages are repeated once for a total of two and then slime is running. I don't know if there are other issues because with the error messages, I comment out the load entries in my .emacs file to disable log4cl.

I'm using the newer github release of slime on a Linux-mint-14-kde distro.

Log levels of parent loggers are not applied to messages of children.

I have several packages with different log levels writing to different files and I create a file appender for root logger which should write all ERROR messages from all loggers to error.log. Currently messages are only filtered by the logger they're initiated at so if one package's logger is set to DEBUG root logger would write debug messages to error.log even if it's set to ERROR.

Here's my (log:config)

ROOT, ERROR
|
+-(1)-#<DAILY-FILE-APPENDER {131D9559}>
|     with #<PATTERN-LAYOUT {EC39B39}>
|          :conversion-pattern
|            "%&%<{nopretty}%I%;<;;>;-5p [%D{%H:%M:%S}] %g{}{}{:downcase} (%C{}{ }{:downcase})%2.2N - %:_%m%>%n"
|     :immediate-flush       NIL
|     :flush-interval        1
|     :stream-owner          T
|     :rollover-check-period 60
|     :name-format           #P"/home/naryl/eshop-logs/eshop.log"
|     :backup-name-format    NIL
|     :utc                   NIL
|     :message-count         2962
|
+-ESHOP, DEBUG
| |
| +-(1)-#<THIS-CONSOLE-APPENDER {131E4B31}>
|       with #<PATTERN-LAYOUT {BB97C89}>
|            :conversion-pattern
|              "%&%<{nopretty}%I%;<;;>;-5p [%D{%H:%M:%S}] %g{}{}{:downcase} (%C{}{ }{:downcase})%2.2N - %:_%m%>%n"
|       :immediate-flush NIL
|       :flush-interval  1
|       :stream-owner    NIL
|       :stream          #<SB-SYS:FD-STREAM for "the terminal" {B322409}>
|       :message-count   2962
|
+-SEARCH-TIPS, TRACE
  |
  +-(1)-#<DAILY-FILE-APPENDER {11BC4DE9}>
        with #<PATTERN-LAYOUT {11BC2651}>
             :conversion-pattern
               "%&%<%I%;<;;>;-5p [%D{%H:%M:%S}] %g{}{}{:downcase}%:; ;F (%C{}{ }{:downcase})%2.2N - %:_%m%>%n"
        :immediate-flush       NIL
        :flush-interval        1
        :stream-owner          T
        :rollover-check-period 60
        :name-format           "/home/naryl/eshop-logs/search-tips.log"
        :backup-name-format    NIL
        :utc                   NIL
        :message-count         0

problem on ABCL

See fukamachi/clack#74

public API changed: log:config :daily doesn't accept a pathname anymore, only strings

Is it intentional?

See also cl-test-grid/cl-test-grid#16

Unable to install `Log4Slime`

(ql:quickload :log4slime)

fails (I am attaching the stack-trace). All other packages load fine (including log4cl). I am using Emacs 24.5.1 with SLIME 2.14 and Clozure CL 1.9.

The value (SWANK-LOADER::SWANK
           SWANK-LOADER::BACKEND) is not of the expected type (OR
                                                               STRING
                                                               SYMBOL
                                                               CHARACTER).
   [Condition of type TYPE-ERROR]

Restarts:
 0: [TRY-RECOMPILING] Recompile swank-loader and try loading it again
 1: [RETRY] Retry loading FASL for #<SWANK-LOADER-FILE "swank" "swank-loader">.
 2: [ACCEPT] Continue, treating loading FASL for #<SWANK-LOADER-FILE "swank" "swank-loader"> as having been successful.
 3: [RETRY] #<error printing RESTART #xB56ED6EE>
 4: [CLEAR-CONFIGURATION-AND-RETRY] #<error printing RESTART #xB56ED716>
 5: [ABORT] Give up on "log4slime"
 --more--

Backtrace:
  0: (CCL::COPY-STRING-ARG (SWANK-LOADER::SWANK SWANK-LOADER::BACKEND))
  1: (STRING-DOWNCASE (SWANK-LOADER::SWANK SWANK-LOADER::BACKEND) :START 0 :END NIL)
  2: ((:INTERNAL SWANK-LOADER::SRC-FILES) (SWANK-LOADER::SWANK SWANK-LOADER::BACKEND))
  3: (SWANK-LOADER::SRC-FILES ((SWANK-LOADER::SWANK SWANK-LOADER::BACKEND) SWANK-LOADER::METERING (SWANK-LOADER::SWANK SWANK-LOADER::CCL) (SWANK-LOADER::SWANK SWANK-LOADER::GRAY) ..))) #P"/home/egarrulo/..
  4: (SWANK-LOADER::COMPILE-CONTRIBS :SRC-DIR #P"/home/egarrulo/emacs/lisp/site-lisp/slime/slime-2.14/contrib/" :FASL-DIR #P"/home/egarrulo/.cache/slime/fasl/2015-06-01/clozure-version_1.9-r15756__(..
  5: (SWANK::RUN-HOOK (SWANK-LOADER::COMPILE-CONTRIBS SWANK::INIT-LOG-OUTPUT))
  6: (CCL::%%BEFORE-AND-AFTER-COMBINED-METHOD-DCODE (NIL #<STANDARD-METHOD ASDF/ACTION:PERFORM (ASDF/LISP-ACTION:LOAD-OP SWANK-LOADER::SWANK-LOADER-FILE)> . -312467164))
  7: (CCL::%%STANDARD-COMBINED-METHOD-DCODE ((#<STANDARD-METHOD ASDF/ACTION:PERFORM :BEFORE (ASDF/OPERATION:OPERATION ASDF/COMPONENT:COMPONENT)>) ..))) -312467164)
  8: (NIL #<Unknown Arguments>)
  9: (CCL::%CALL-NEXT-METHOD (NIL #<STANDARD-METHOD ASDF/ACTION:PERFORM-WITH-RESTARTS (T T)> . -312467097))
 10: (#<STANDARD-METHOD ASDF/ACTION:PERFORM-WITH-RESTARTS (ASDF/LISP-ACTION:LOAD-OP ASDF/LISP-ACTION:CL-SOURCE-FILE)> #<LOAD-OP > #<SWANK-LOADER-FILE "swank" "swank-loader">)
 11: (CCL::%CALL-NEXT-METHOD (NIL #<STANDARD-METHOD ASDF/ACTION:PERFORM-WITH-RESTARTS (T T)> . -312467097))
 12: (#<STANDARD-METHOD ASDF/ACTION:PERFORM-WITH-RESTARTS :AROUND (T T)> #<LOAD-OP > #<SWANK-LOADER-FILE "swank" "swank-loader">)
 13: (CCL::%%STANDARD-COMBINED-METHOD-DCODE (#<STANDARD-METHOD ASDF/ACTION:PERFORM-WITH-RESTARTS :AROUND (T T)> ..)) -312467097)
 14: (NIL #<Unknown Arguments>)
 15: (#<STANDARD-METHOD ASDF/PLAN:PERFORM-PLAN (LIST)> ((#<COMPILE-OP > . #<SYSTEM "alexandria">) (#<COMPILE-OP > . #<MODULE "bordeaux-threads" "src">) (#<COMPILE-OP > . #<SYSTEM "bordeaux-threads">) ..)))..
 16: (CCL::%CALL-NEXT-METHOD (NIL #<STANDARD-METHOD ASDF/PLAN:PERFORM-PLAN (LIST)> . -312467036))
 17: (CCL::CALL-WITH-COMPILATION-UNIT #<COMPILED-LEXICAL-CLOSURE (:INTERNAL CCL::WITH-COMPILATION-UNIT-BODY (ASDF/PLAN:PERFORM-PLAN :AROUND (T))) #xB56ED52E> :OVERRIDE NIL)
 18: (#<STANDARD-METHOD ASDF/PLAN:PERFORM-PLAN :AROUND (T)> ((#<COMPILE-OP > . #<SYSTEM "alexandria">) (#<COMPILE-OP > . #<MODULE "bordeaux-threads" "src">) ..))))
 19: (CCL::%%STANDARD-COMBINED-METHOD-DCODE (#<STANDARD-METHOD ASDF/PLAN:PERFORM-PLAN :AROUND (T)> #<STANDARD-METHOD ASDF/PLAN:PERFORM-PLAN (LIST)>) -312467036)
 20: (NIL #<Unknown Arguments>)
 21: (CCL::%CALL-NEXT-METHOD (NIL #<STANDARD-METHOD ASDF/PLAN:PERFORM-PLAN (T)> . -312466983))
 22: (CCL::CALL-WITH-COMPILATION-UNIT #<COMPILED-LEXICAL-CLOSURE (:INTERNAL CCL::WITH-COMPILATION-UNIT-BODY (ASDF/PLAN:PERFORM-PLAN :AROUND (T))) #xB56ED5B6> :OVERRIDE NIL)
 23: (#<STANDARD-METHOD ASDF/PLAN:PERFORM-PLAN :AROUND (T)> #<ASDF/PLAN:SEQUENTIAL-PLAN #x18E755E6>)
 24: (CCL::%%STANDARD-COMBINED-METHOD-DCODE (#<STANDARD-METHOD ASDF/PLAN:PERFORM-PLAN :AROUND (T)> #<STANDARD-METHOD ASDF/PLAN:PERFORM-PLAN (T)>) -312466983)
 25: (NIL #<Unknown Arguments>)
 26: (#<STANDARD-METHOD ASDF/OPERATE:OPERATE (ASDF/OPERATION:OPERATION ASDF/COMPONENT:COMPONENT)> #<LOAD-OP :VERBOSE NIL> #<SYSTEM "log4slime"> :VERBOSE NIL)
 27: (CCL::%CALL-NEXT-METHOD ((NIL) #<STANDARD-METHOD ASDF/OPERATE:OPERATE (ASDF/OPERATION:OPERATION ASDF/COMPONENT:COMPONENT)> #<LOAD-OP :VERBOSE NIL> #<SYSTEM "log4slime"> :VERBOSE NIL))
 28: ((:INTERNAL (ASDF/OPERATE:OPERATE :AROUND (T T))))
 29: (#<STANDARD-METHOD ASDF/OPERATE:OPERATE :AROUND (T T)> #<LOAD-OP :VERBOSE NIL> #<SYSTEM "log4slime"> :VERBOSE NIL)
 30: (CCL::%%STANDARD-COMBINED-METHOD-DCODE (#<STANDARD-METHOD ASDF/OPERATE:OPERATE :AROUND (T T)> (#<STANDARD-METHOD ASDF/OPERATE:OPERATE :BEFORE #> #<#>) NIL ..))) -312466911)
 31: (NIL #<Unknown Arguments>)
 32: (CCL::%CALL-NEXT-METHOD ((NIL) #<STANDARD-METHOD ASDF/OPERATE:OPERATE (SYMBOL T)> ASDF/LISP-ACTION:LOAD-OP "log4slime" :VERBOSE NIL))
 33: ((:INTERNAL (ASDF/OPERATE:OPERATE :AROUND (T T))))
 34: (ASDF/CACHE:CALL-WITH-ASDF-CACHE #<COMPILED-LEXICAL-CLOSURE (:INTERNAL (ASDF/OPERATE:OPERATE :AROUND (T T))) #x18E73AC6> :OVERRIDE NIL :KEY NIL)
 35: (#<STANDARD-METHOD ASDF/OPERATE:OPERATE :AROUND (T T)> ASDF/LISP-ACTION:LOAD-OP "log4slime" :VERBOSE NIL)
 36: (CCL::%%STANDARD-COMBINED-METHOD-DCODE (#<STANDARD-METHOD ASDF/OPERATE:OPERATE :AROUND (T T)> (#<STANDARD-METHOD ASDF/OPERATE:OPERATE :BEFORE #>) NIL ..) -312466828)
 37: (NIL #<Unknown Arguments>)
 38: (#<STANDARD-METHOD ASDF/OPERATE:OPERATE :AROUND (T T)> ASDF/LISP-ACTION:LOAD-OP "log4slime" :VERBOSE NIL)
 39: (CCL::%%STANDARD-COMBINED-METHOD-DCODE (#<STANDARD-METHOD ASDF/OPERATE:OPERATE :AROUND (T T)> (#<STANDARD-METHOD ASDF/OPERATE:OPERATE :BEFORE #>) NIL ..) -312466793)
 40: (NIL #<Unknown Arguments>)
 41: (QUICKLISP-CLIENT::CALL-WITH-MACROEXPAND-PROGRESS #<COMPILED-LEXICAL-CLOSURE (:INTERNAL QUICKLISP-CLIENT::APPLY-LOAD-STRATEGY) #x18E73FF6>)
 42: (QUICKLISP-CLIENT::AUTOLOAD-SYSTEM-AND-DEPENDENCIES "log4slime" :PROMPT NIL)

error in format-time on LispWorks

Because there is a small error in format-time, log4cl does not output anything all on LispWorks.
In pattern-layout.lisp, the call to decode-universal-time is:

(decode-universal-time ut (if utc-p 0))

When utc-p is nil, decode-universal-time is called with the wrong timezone.
I temporarily fixed this issue by removing the if form:

(decode-universal-time ut 0)

log4cl now works for me.
Thanks for this fine library!

When running ros install arrival , I get an error related to log4cl

Hello,

When running ros install arrival , I get an error related to log4cl

To load "arrival":
  Load 1 ASDF system:
    arrival
; Loading "arrival"
..[1/3] System 'arrival' found. Loading the system..
; 
; caught ERROR:
;   READ error during COMPILE-FILE:
;   
;     Lock on package SB-C violated when interning LAMBDA-PARENT while in package
;     LOG4CL-IMPL.
;   See also:
;     The SBCL Manual, Node "Package Locks"
;   
;     (in form starting at line: 99, column: 0, position: 3779)
Aborted during step [1/3].
Unhandled UIOP/LISP-BUILD:COMPILE-FILE-ERROR in thread #<SB-THREAD:THREAD tid=80526 "main thread" RUNNING
                                                          {10044A0113}>:
  COMPILE-FILE-ERROR while
  compiling #<CL-SOURCE-FILE "log4cl" "src" "naming-sbcl">

Any idea where this comes from ?

Thanks

I haven't thanked you enough.

log4cl is wonderful, THANK YOU!!

Consider using Conium rather than SWANK-BACKEND

There isn't much of a focus to keep the SWANK API stable beyond the needs of SLIME itself. Have you considered using Conium instead?

Does not build in SBCL 1.1.6+

I'm using the latest SBCL from git, and when I build log4cl, I get this error:

; caught ERROR:
;   READ error during COMPILE-FILE: Lock on package SB-C violated when interning HAIRY-ARG-PROCESSOR while in package LOG4CL-IMPL.

Breakage due to ASDF package changes

Recent versions of ASDF do not export GETENV or any utilities anymore.
This breaks log4cl.

The fix is to either
1- use ASDF-UTILS that exports all these utilities, or
2- use internal symbols like ASDF::GETENV if you really can't or won't depend on ASDF-UTILS.

Please test with a new ASDF (such as 2.25), without loading any system-provided ASDF via require.
My apologies for the breakage.

Memory fault with non-logger in explicit logger position

On Thu, May 10, 2012 at 5:25 PM, Alistair Gee ...... wrote:
Hi,

I am using log4cl (latest via quicklisp) and SBCL 1.0.55 on 64-bit Linux.

The following will cause a memory fault:

    (defun foo ()
      (handler-case
          (assert nil)
        (error (e)
          (log:i e))))

    CL-USER> (foo)
    CORRUPTION WARNING in SBCL pid 15228(tid 140698642544384):
    Memory fault at 336 (pc=0x100e41a963, sp=0x7ff6f49bdbd0)
    The integrity of this image is possibly compromised.
    Continuing with fingers crossed.

I am actually trying to print out an error that I've defined as:

    ;;; define my own error type
    (define-condition my-error (error)
      ((text :initarg :text :reader text :type (or null string)))
      (:report (lambda (c s)
                 (declare (type stream s))
                 (format s "my error: ~a" (text c)))))

    ;;; (format) can print out the error without crashing.
    (defun foo2 ()
      (handler-case
          (assert nil nil 'my-error :text "hello")
        (error (e)
          (format t "I can print out the error via (format): ~A" e))))

    ;;; However, (log:i) will crash SBCL when attempting to print out the error.
    (defun foo3 ()
      (handler-case
          (assert nil nil 'my-error :text "hello")
        (error (e)
          (log:i e))))

This is certainly a SBCL bug, but I am not sure where to start looking. Let me know what how I can help you track this down.

log to file on SBCL looses last two log messages

Hello.

I have a program which logs to file and console.

log4cl is configured using
(log:config :daily log-file)

On CCL it works as expected.
But on SBCL I see that log file looses two last log messages, while the console shows all the messages.

sbcl-1.0.57-linux-x86
log4cl is from quicklisp 2012-07-03.

PLEASE REPORT BUGS IN MAINTAINED FORK https://github.com/sharplispers/log4cl

Since this repository is abandoned and unmaintained it has been forked here: https://github.com/sharplispers/log4cl. It still happens to be the first result in searches since it is the original repository and many programmers report issues mistakenly here.

The version from sharplispers repository is the one present on Quicklisp and has numerous bugs fixed. If the author decides to maintain this repository again we will be happy to backport fixes. Please report new issues here: https://github.com/sharplispers/log4cl/issues.

Thank you.

Binary logging idea

1. Add a new log level like attribute to each logger state, called binary log level, that follows exactly same inheritance rules as regular log level.
2. When performing a check whenever any logging is to be performed, in (logging-enabled-for), consult both regular log level and binary log level.
3. Change appender-do-append generic will gain an extra argument, orig-args-vector
4. orig-args-vector will be initialized, for log statements with the format control string, as all arguments to the format call. For expression logging , it will be all arguments in order.
5. The vector will only be created at call site, if there there were any binary log level reachable, so if no binary log levels reachable, it will be

This will allow people to write binary binary appenders, that examine the actual arguments, and not their textual representation..

One example would be writing the the binary representation of each log statement arguments into a binary log file, with additional tools that analyze the file. This method should be much faster both at runtime, and at analyzing part, due to no need for formatting arguments into text

log4cl:project-options doesn't work.

Attempting to call the project-options macro as log4cl:project-options raises the following condition (at least on sbcl):

The symbol "PACKAGE-OPTIONS" is not external in the LOG4CL-IMPL package.

However calling it as log4cl::project-options works fine.
I also get that error if I try to describe 'log4cl:project-options, but agin describing 'log4cl::project-options works fine. I have no idea what would cause this to happen.

Add syntax sugar for logging macros to drop innermost level of auto-naming

There is an often used pattern is Lisp for writing wrappers like this:

(defun call-with-wrapping (thunk)
  (unwind-protect 
      (progn
         (log:trace "Wrapping is on")
         (funcall thunk))
    (log:trace "Wrapping is off")

(defmacro with-wrapping (&body body)
  `(call-with-wrapping (lambda () ,@body))

(defun foobar ()
  (call-with-wrapping ...))

Currently above results in log category auto-naming making the log category
of package.foobar.call-with-wrapping.lambda, which is too much information we don't want.

Its possible to fix the above pattern, by adding a logger object argument to call-with-wrapping, and passing the logger object to macro like this.

(defun call-with-wrapping (logger thunk)
  (unwind-protect 
      (progn
         (log:trace :logger logger "Wrapping is on")
         (funcall thunk))
    (log:trace :logger logger  "Wrapping is off")

(defmacro with-wrapping (&body body)
  `(call-with-wrapping (log:category) (lambda () ,@body))

(defun foobar ()
  (call-with-wrapping ...))

But it would be nice if above can be done without such workaround, by adding some syntax sugar to logging macros, that indicate that auto category naming should drop a level, something like (log:trace /// ....) or (log:trace ***) to indicate that naming should drop 3 levels

with-output-to-string resutl can't be pased to log:info

(log:info "hello") => works

(log:info (with-output-to-string (s) (format s "hello"))) =>

value "hello" is not of the expected type LOG4CL-IMPL::LOGGER.
[Condition of type TYPE-ERROR]

This is CCL-1.8, Windows.

Should serialized-appender use a recursive lock?

Consider the following:

(with-simple-restart (abort "Abort")
  (handler-bind 
    ((error (lambda (condition)
               (log:error "caught error: ~A" condition)
               (abort))))
    (log:info "~A")
    :finished))

(log:info "~A") is obviously wrong since there are not enough format arguments. One would expect this error to be caught and reported by the outer "catch-all" handler-bind. However, since the format error is signaled while in appender-do-append, the (log:error "caught error: ~A" condition) code re-enters appender-do-append and causes a recursive lock attempt. As a consequence, a relatively harmless format error in logging code escalates even beyond the intended "catch-all" error handling.

I can imagine two possible improvements:

1. Catch errors of his kind in log4cl and print a log message like <INFO> [20:08:12] cl-user () - <<error printing log message>>. This approach would similar to the usual <SOME-CLASS <<error printing object>> >-behavior. This solution would not change the control flow, i.e. return :finished in the above example, since no error would be signaled.
2. Use a recursive lock. In the above example this would lead to the output (in SBCL):

<ERROR> [20:08:12] cl-user () -
  caught error: error in FORMAT: required argument missing
  ~A
   ^

This solution would change the control flow since the format-error would still be signaled.

1. Make one of the two behaviors selectable as a configuration option or via a special variable *debug-log-statements?* :)

In log4slime split the time and thread name regexp's and relax thread one slightly

Currently everything between debug level and package, needs to match log4slime-time-regexp, including thread names. And it seems weird characters in thread names are more common then anticipated.

Split the regexp into two, one for date/time, and one for thread part, and relax the thread/ndc regexp, so it can handle most punctuation

Also change them to (defcustom) instead of defvars.

dependency on sb-posix is not declared

based on
commit d6293f9
Author: Max Mikhanosha [email protected]

compilation with sbcl fails, when it reaches the reference to sb-posix:getpid.

adding a conditional :sb-posix to the system dependencies resolves the problem.