This is our current documented pattern for warning logs:
this.logger.warn("Failed to resolve the entity [{}]. Cause: [{}]", entityReference, getRootCauseMessage(e));
The rationale is that a warning indicates that the system has not become unstable and has recovered from the problem and it can continue to be up. Thus we only log the root cause to help with any light debugging needed and we don’t spam the logs with stacktraces (that we reserve for errors so that they can be quickly identified in the logs, and also provide the max details).
I’m wondering if we couldn’t improve the pattern for logger.warn() by introducing a static method helper that we would use like this:
this.logger.warn("Failed to resolve the entity [{}]. Cause: [{}]", entityReference, rootCauseMessage(e));
The rootCauseMessage() method would do the following:
If the logging level is <= debug (ie debug or trace), then display the full stack trace
If the logging level is > debug (ie warn, error, info), then display the root cause message (i.e. calling getRootCauseMessage(e)).
The goal would be to have a way to get the full stack trace when debug mode is on, for the cases when we want to see the details. Ofc this would make the logs bigger when in debug mode and XWiki slower but the debug mode is not supposed to be performant.
Note that the JIT would inline the method so there would be only the IF cost to pay at runtime, when logging level > debug. That’s pretty low I think.
Honestly, I’m not sure if this is a good idea or not. Curious to have your POV.
Feels too subtle/hard to discover to me, in particular with a method name that seems to lie about what it does (sometimes returning a full stack trace doesn’t seem to be covered by the name). When reading the code, how would an admin who checks for a debug log to enable find out that enabling debug logging would change the log output? That part might be better with a name like rootCauseMessageOrStackTraceWhenDebugEnabled.
The other question I have is regarding job log storage and display. If debug log is enabled while the job runs, it means that we have stack traces as part of the message, always displayed even if, e.g., the job log display has been customized to never display them. This might completely disrupt the job log display, making the log basically unusable. We apparently currently don’t filter the job log based on level when displaying it (filters are applied when saving) but still, we lose the potential ability to filter out debug logs with stack traces when reading job logs.
In general, I think it’s not a good idea to log a stack trace as part of the log message. It prevents any automated processing (analyzing and collecting stack traces in some log collection tool) and badly interacts with the UI. To me, it feels like we should add a rule to explicitly forbid passing a stack trace as part of the log message/a regular parameter.
We could have a helper method to automate this debug + warn log, but I think we should either keep it two separate log events or pass the exception as a proper exception argument to the logger when debug logging is enabled.
I wasn’t proposing that specific name, only the idea, and naming is easy to fix. But you convinced me that the helper method is the wrong level entirely. New proposal below.
Agreed. Thinking about it more, the problem is not what we log, it’s how the console renders it.
New Proposal
1. Dev rule: always pass the exception as an exception argument, for warn() exactly as for error(): warn("Failed to save [{}]", reference, e). One simple rule, nothing hidden in the message, nothing lost for log collectors.
2. Decide how much to print at rendering time, not at logging time. Logback lets us plug a custom ThrowableHandlingConverter into the console pattern, which gets the whole event and can decide per level: for WARN print only Root cause: [<root cause class>: <message>], for anything else print the full stack trace exactly as today. I prototyped it in [Misc] Prototype rendering only the root cause of warnings in the console by vmassol · Pull Request #1877 · xwiki/xwiki-commons · GitHub (draft): it works, it’s a single class, and it needs no change at all in how we call the logger. Note that our current pattern contains no throwable conversion word at all, and Logback then silently appends a full-stack-trace one — that’s why we get stack traces everywhere today.
Important: this changes only the console rendering. The exception remains a first-class part of the log event, so the job UI keeps its current behaviour (logging_macros.vm already shows the root cause message and folds the full stack trace) and any log collector with its own encoder still receives everything. A one-line root cause in the console is not a stack trace that tools need to parse, so I don’t think it conflicts with your point above.
3. A logging.warn.stacktrace property in xwiki.properties (default false) to get full stack traces back for warnings. Better than my initial “when debug is enabled” idea: explicit, discoverable, and independent from log levels, so you don’t have to turn on a flood of debug logs to get one stack trace.
4. Throttling comes for free. Logback ships ch.qos.logback.classic.turbo.DuplicateMessageFilter (allowedRepetitions, cacheSize), so “log this at most N times” is pure logback.xml configuration, no code on our side.
The general logic sounds appealing, but it’s kind of an API breakage in practice (an extension would suddenly end up losing the stack trace it asked for in the call).
For warn(), it’s a change when it was used with a full stack trace (which is not supposed to be the case for contrib extensions as they’re supposed to follow the dev.xwiki.org best practices). Now it could be considered a small change since it’d be possible to set the new property and then you’d get the stack traces for warn (if you need it).
Now, it’s also easy to configure logback.xml to use a different appender format for some logs. For example, you can configure that for org.xwiki.contrib.* , you’ll not use the %xwikiEx% conversion word (and thus use %ex%, which is the default).
So I think it would be acceptable to document this in the backward compatibility section of the release notes. WDYT?
I wasn’t aware of this construct. I need to check the code. But indeed using a marker sounds like a possibility.
You’re right, and it’s the clearest counter-example there is: warnWithStackTrace() builds an IllegalStateException whose only payload is the call site, so reducing it to Root cause: [java.lang.IllegalStateException: Wiki part of XClass reference is wrong] deletes exactly what the method exists to produce. Your marker suggestion is the right answer and it fits an idiom we already have — Logger.ROOT_MARKER (root), LogEvent.MARKER_BEGIN/MARKER_END (xwiki.begin/xwiki.end).
Added to the prototype (I’ve updated the PR):
// org.xwiki.logging.Logger, next to ROOT_MARKER
Marker STACKTRACE_MARKER = MarkerFactory.getMarker("xwiki.stacktrace");
// XWikiDocument.warnWithStackTrace
LOGGER.warn(STACKTRACE_MARKER, logMessage, ArrayUtils.add(parameters, exception));
The converter checks it with event.getMarkerList() + Marker.contains(name), so a nested marker works too. I also fixed LogbackEventGenerator, which used the deprecated event.getMarker() and would have dropped one of two markers on the way into LogEvent; with that fixed the marker reaches the job log as well, and logging_macros.vm can use the same signal to auto-expand instead of folding. It’s semantic metadata rather than a console trick, which also answers Michael’s point about log collectors.
On the API-breakage half: I was wrong in my previous message. You can’t use %ex for some loggers only — a pattern belongs to an encoder and an encoder to a single appender, so per-package rendering means a second appender plus additivity="false", and two FileAppenders on the same file need prudent mode (~3x the cost per event, restricted rolling). So I moved the scoping into the converter, which is the only place that sees the logger name:
One appender, one file, no additivity games. The property takes a comma-separated list and each entry matches that logger and everything below it, and the same thing can be written in the pattern (%xwikiEx{full=org.xwiki.contrib}) since logback splits the option list on commas. Note converterClass is deprecated in current logback — it’s class now.
Sounds good to me in principle. I have one possible concern: Our job log viewer currently doesn’t cope well when displaying a huge job log, see XWIKI-16647. While we need to fix that, I fear that systematically adding stack traces to all warnings could blow up the log output a lot and might trigger the OOM much easier on some jobs.
I’m not convinced that’s a good idea as it destroys the overview that is provided by the log viewer. I think it is enough that the user can expand the log entry. But I don’t care too much about that part.
I’ve discussed with CC and one idea we reached is the following (which is to throttle exceptions when they’re the same to avoid having them flood the FS logs and the HTML job log UI too). This is based on the assumption that in regular usage we wouldn’t have too many warn() calls and that the flood issue you raised would appear when something is wrong and the code iterates on lots of items (e.g. doing a large XAR import, doing a migration, etc).
The idea
Every warn(msg, e) keeps passing its exception, exactly as the rule wants. But on the way into the job log we ask one question: “have I already stored this exact stack trace?” If yes, we store the event without the frames and point at the first one. The message and its arguments — the part that differs per occurrence and that the user needs — are always stored in full.
A job that fails on 10 000 documents then writes one stack trace instead of 10 000, and the 9 999 others cost ~150 bytes each instead of ~20 KB.
Where it hooks
AbstractJobStatus pushes a listener that funnels every log call on the job thread into a LoggerTail:
We wrap that tail in a decorator. One class, one interesting method, everything else delegates:
@Override
public void log(LogEvent logEvent)
{
Throwable throwable = logEvent.getThrowable();
if (throwable == null) {
this.tail.log(logEvent);
return;
}
synchronized (this) {
long fingerprint = fingerprint(throwable);
Integer firstOccurrence = this.firstOccurrences.get(fingerprint);
if (firstOccurrence == null) {
// Never seen: store the trace in full and remember at which index it landed.
// size() is the index this event is about to get, since the tail only appends.
this.firstOccurrences.put(fingerprint, this.tail.size());
this.tail.log(logEvent);
} else {
// Seen: keep the message and the arguments, replace the frames by a reference.
this.tail.log(new LogEvent(logEvent.getMarker(), logEvent.getLevel(), logEvent.getMessage(),
logEvent.getArgumentArray(), new RepeatedThrowable(throwable, firstOccurrence),
logEvent.getTimeStamp()));
}
}
}
Why a decorator and not AbstractLoggerTail (which the handoff guessed): LogQueue implements LoggerTail directly and never goes through AbstractLoggerTail, so in-memory job logs would be silently missed.
The fingerprint
Hash the class names and the frames of the whole cause chain — and deliberately not the exception messages, because those usually contain the varying part (“Document not found”), which would make every occurrence look unique and defeat the whole thing:
private long fingerprint(Throwable throwable)
{
long hash = 1;
for (Throwable current = throwable; current != null; current = current.getCause()) {
hash = 31 * hash + current.getClass().getName().hashCode();
for (StackTraceElement frame : current.getStackTrace()) {
hash = 31 * hash + frame.hashCode();
}
}
return hash;
}
(needs a depth cap — getCause() chains can be self-referential). Dropping the messages from the key loses nothing, because each occurrence still carries its own message in the placeholder — so what the log UI displays is unchanged.
The placeholder
public class RepeatedThrowable extends Throwable
{
private final int firstOccurrence;
public RepeatedThrowable(Throwable original, int firstOccurrence)
{
// No cause, no writable stack trace: nothing to fill in and nothing to serialize.
super(ExceptionUtils.getRootCauseMessage(original), null, false, false);
this.firstOccurrence = firstOccurrence;
}
}
writableStackTrace = false means the JVM skips fillInStackTrace() entirely and getStackTrace() returns empty — so it is cheap to create and cheap to store.
The gotcha I checked:SafeThrowableConverter.marshal() writes only detailMessage, cause and stackTrace — its whole job is to “skip any custom field that might make XStream try to serialize the world”. So firstOccurrence would be silently dropped on write and come back as 0. The fix is a small RepeatedThrowableConverter registered next to it in SafeXStream (line 70), which writes that one extra int. Both classes are in the same package and the module already depends on logging-api, so this costs nothing — but it is exactly the kind of thing that would have looked fine in review and been broken at runtime.
What the user sees
Nothing changes on the surface. logging_macros.vm#printLog already displays the root-cause one-liner and folds the frames, and RepeatedThrowable carries that same one-liner. The only difference is what happens when you expand a repeat: instead of frames rendered inline, it shows the first occurrence’s trace, fetched by index.
Two honest limits worth knowing up front:
You can’t show “×10 000” on the first line. The log file is append-only with a position index — once event #1 is written you cannot go back and increment a counter on it. The count can only be shown on the repeats (“same stack trace as entry N”), or computed at read time.
The dedup map must be bounded (LRU, generous default). A job with 10 000 genuinely distinct traces is not helped by throttling, and shouldn’t be allowed to grow the map without limit — when it’s full, fall back to storing the trace in full. Throttling is best-effort, never a correctness requirement.
This simplifies the plan
Throttling at capture fixes the FS and the UI in one move: the repeated events don’t contain frames, so there is nothing to write and nothing to render. That means fold-as-fetch is no longer required — it becomes an optimisation for the remaining distinct traces, and for the “expand a repeat” case above. You could ship the rule change (#1877) with throttling alone and track on-demand rendering separately, which is a much smaller thing to ask Michael to agree to.
Note: what CC refers to as “fold-as-fetch” is the idea that in the Job log UI we could fetch the details only when unfolding an event. This is something that could be added later on if what is proposed above is not enough, but it’s orthogonal.
WDYT? It would cost a little bit of memory (through the LRU cache) but that’s probably acceptable.
Feels like a very complex solution to me that is fragile, and it is also not clear to me if we would still store all exception messages or only one (if it’s the latter, we might lose information, if it’s the former, it might be quite complex to make sure that the displayed messages are correct). The client-side code sounds complex and will break the moment we move to a real paginated log display (as it won’t just have the previous exception available). It feels to me like implementing an actual paginated log display, possibly based on Live Data, could be easier than this plan.
Also, note that I’m working (well, worked, paused at the moment) on moving the whole job log into the database, so every log entry will be a row in a database table. Some fields of the log while be stored plain, and we will have the full serialized log entry in one big text. This should make the whole “retrieve that one exception” or pagination over the log much more efficient.
To add to the planned work, my current plan, implemented as a prototype, but also waiting for feedback at Moving job statuses and logs out of the permanent file storage - #10 by MichaelHamann is that while the storage for the job log displayer is the database, there will still be log files in the file system for cases where the job log displayer cannot be accessed, handled by plain LogBack, so whatever you’ll implement for that could be re-used there.
Thx. I like the idea of a LD for the job log UI (I guess we’ll need to add entries to the LD dynamically and display the last log first so that it moves at the same time as the log appear - that may be less usable/intuitive though, to be checked with @tkrieck ). I think it’s more complex than what I proposed but it brings more advantages (filtering, addresses job logs size in general and not just for stacktraces). That said, it solves the issue only if the job log FS is moved to a scalable store (RDBMS or other - on this topic I’m far from sure that the RDBM is the good choice, I’d seen an ES or OpenSearch store as more suited, but I haven’t researched it - I’m a bit worried about the perf hit we’ll take, even if done async).
So we have 2 options at this point in time:
Implement this thread’s proposal now and then apply the new practice of passing exceptions to new code, and wait for the job logs LD + the store to do a massive sweep of warn() calls to pass exceptions.
Park the work and wait for the LD + store changes before resuming.
I guess 2) makes the most sense so I’m going to stop working on this.