Pascal Debugging Logging

pascal-debugging-logging

Runtime diagnostics for mORMot 2 Pascal projects: wiring TSynLog (the logger declared in mormot.core.log.pas), choosing levels from TSynLogLevel (sllError, sllWarning, sllStackTrace, sllEnter, sllLeave, sllInfo, sllDebug, sllTrace, sllException), capturing per-method timings via ISynLog, reading FastMM4 / mormot.core.fpcx64mm leak reports, and resolving raw return addresses from a stack trace back to source lines via Delphi .map or FPC -gw3 DWARF. This skill teaches what the logger does and how to read what it produces; it stops where test design (test-driven-development) and four-phase root-cause analysis (systematic-debugging) begin. It assumes the build flags of delphi-build / fpc-build are already in place: a project that does not emit a .map or a .dbg file at link time has no symbols to recover, and no amount of logging will turn raw 0x00000000007a3c1d into mormot.core.json:1234.

When to use

• Adding a logger to a project: declaring a TSynLogClass (or using the default TSynLog), configuring TSynLogFamily (Level, LevelStackTrace, DestinationPath, PerThreadLog, RotateFileCount, AutoFlushTimeOut), and emitting log entries via TSynLog.Add.Log(sllInfo, ...) or TSynLog.Family.SynLog.Log(...).
• Choosing log levels per environment: production typically uses LOG_NFO (info + warnings + errors + monitoring), development LOG_VERBOSE, error-only deployments LOG_ERR. Stack traces always travel with sllError, sllException, sllExceptionOS, sllLastError, sllStackTrace via the default LevelStackTrace set.
• Per-method timing with ISynLog: TSynLog.Enter(self, 'MyMethod') or the more efficient TSynLog.EnterLocal(local, self, 'MyMethod'), which records sllEnter on entry and sllLeave with elapsed microseconds when the interface goes out of scope.
• Reading a FastMM4 (Delphi) or mormot.core.fpcx64mm (FPC) leak report at shutdown: matching the call-site fingerprint to a unit + line, distinguishing real leaks from finalization-order false positives, telling shared-string interning artifacts from genuine retention.
• Resolving an address-only stack trace (error $0000000000401abc) to a source line: building Delphi with -GD so a detailed .map exists, building FPC with -gw3 -gl so DWARF + line-info travel with the binary, and pointing the resolver (mORMot's built-in, addr2line, Map2DWARF) at the artefact.
• Hunting EAccessViolation, EAssertionFailed, EOutOfMemory, EDivByZero and other Exception descendants by enabling Family.HandleExceptions := true so every raised exception gets logged with its stack trace before it propagates.
• Capturing live performance traces in long-running services: mormot.core.perf.TSynMonitor family for per-operation counters (count, total/min/max time, throughput) when ISynLog per-method timing is too coarse-grained or already enabled at every entry.

When NOT to use

• Writing failing tests first, the RED-GREEN-REFACTOR loop, choosing TSynTestCase / TSynTestsLogged shapes. Use test-driven-development.
• Following the four-phase root-cause workflow (Capture, Reproduce, Bisect, Fix) on a specific failure. This skill teaches the instruments; the workflow that drives them is in systematic-debugging.
• Build-time configuration: -V / -GD on Delphi, -gw3 / -gl on FPC, search paths, conditional defines that toggle logging at compile time. Use delphi-build or fpc-build.
• Runtime topology decisions (where the log file lives in production, log shipping to a SIEM, rotation policy across multiple instances). Those are deployment choices and belong in mormot2-deploy.
• RawUtf8, TDocVariant, RTTI, conditional defines used in the snippets. Use mormot2-core.

Core idioms

1. Wire TSynLog into a project in three lines

mORMot 2's TSynLog is a singleton-per-class: every TSynLogClass (i.e. class of TSynLog) gets its own TSynLogFamily. The default TSynLog works for most apps; large systems declare TSqlLog, TServerLog, etc. so the .log files separate by concern. Configuration goes through the family, before the first log line:

program myserver;
{$I mormot.defines.inc}
uses
  mormot.core.log,
  mormot.core.os; // for TSynLog stack-trace symbol resolution

begin
  with TSynLog.Family do
  begin
    Level := LOG_VERBOSE;          // every level; use LOG_NFO in production
    DestinationPath := './logs/';  // created on first write
    PerThreadLog := ptIdentifiedInOneFile; // tag thread, single file
    RotateFileCount := 5;          // keep 5 rotated files
    RotateFileSizeKB := 8 * 1024;  // 8 MB before rotation
    AutoFlushTimeOut := 5;         // flush every 5s even if buffer not full
    HandleExceptions := true;      // log every Exception with stack trace
  end;
  TSynLog.Add.Log(sllInfo, 'server starting, pid=%', [GetCurrentProcessId]);
  // ... main loop ...
end.

Level := LOG_VERBOSE should be set last (it triggers the family's first CreateSynLog), and LevelStackTrace already includes sllError, sllException, sllExceptionOS, sllLastError, sllFail, sllDDDError, sllStackTrace by default. There is no separate Initialize to call: the family is constructed lazily on first access. See references/tsynlog-setup.md for the full property table and per-environment level recommendations.

2. Per-method timing via ISynLog / EnterLocal

TSynLog.Enter returns an ISynLog interface whose _AddRef writes sllEnter and whose _Release writes sllLeave with the elapsed time. The interface goes out of scope at the method end, so the leave entry happens automatically on return, raise, or any other exit path:

procedure TOrderService.PostOrder(const order: TOrder);
var
  log: ISynLog;
begin
  log := TSynLog.Enter(self, 'PostOrder');
  // do work
  if Assigned(log) then // nil if sllEnter is not in Family.Level
    log.Log(sllInfo, 'submitted order id=%', [order.ID]);
end; // _Release writes:  20240101 12:34:56  -    01.512.320

For the hot path, prefer EnterLocal, which avoids one IUnknown indirection and is explicitly faster on FPC:

var
  log: ISynLog;
begin
  TSynLog.EnterLocal(log, self, 'HotMethod');
  // ...
  if Assigned(log) then
    log.Log(sllDebug, 'cache hit ratio=%', [hits / total]);
end;

When Family.HighResolutionTimestamp := true, the +/- lines carry hexadecimal microseconds suitable for after-the-fact profiling without re-running. Pair with mormot.core.perf.TSynMonitor when you need aggregated counters (call count, min/max/total time per operation) instead of per-call lines.

3. Make every Exception log its stack trace

The single highest-value setting in TSynLogFamily is HandleExceptions := true. mORMot 2 hooks RaiseException on Windows and the RaiseProc slot on FPC; every raised Exception lands in the log with its message, address, and stack trace, before the regular try/except can swallow it:

TSynLog.Family.HandleExceptions := true;
TSynLog.Family.ExceptionIgnore.Add(EConvertError); // skip noisy ones
TSynLog.Family.ExceptionIgnoreLibrary := true;     // skip exceptions from .bpl

ExceptionIgnore is a class list; ExceptionIgnoreCurrentThread := true toggles per-thread (e.g. inside an Indy worker that raises a lot of EIdConnClosedGracefully). OnBeforeException is a callback if you need conditional filtering. The result in the log file:

20240101 12:34:56 EXC   EAccessViolation ('Access violation at address...') at $00007FF6C123ABCD
20240101 12:34:56 stack $00007FF6C123ABCD mymain.MyMethod (mymain.pas:123)
                         $00007FF6C123AC10 mormot.rest.server.TRestServer.Uri ...

The level marker is EXC for sllException and OSE for sllExceptionOS. sllStackTrace lines follow only when the address resolves; addresses that the resolver cannot map appear as raw hex.

4. Build for stack traces: .map (Delphi) and DWARF (FPC)

mORMot 2's address-to-line resolver reads either a Delphi-style .map file (parsed by mormot.core.log at startup) or an FPC binary with embedded DWARF debug info (read via mormot.core.log + mormot.lib.libcrypto or the OS-native debug API). Without one of these, every stack trace is raw hex, and every leak report is "[allocated at $00007FF6C123ABCD]" with no further information.

• Delphi: build with -GD (or <DCC_MapFile>3</DCC_MapFile> in .dproj) to emit a detailed map. Ship the .map next to the .exe. mORMot reads it on first stack trace.
• FPC: build with -gw3 -gl (DWARF v3 + line numbers). The debug info is embedded in the binary; nothing extra to ship. For smaller binaries, run objcopy --only-keep-debug to split off a .dbg companion file, then objcopy --add-gnu-debuglink to wire the binary back to it.
• Cross-compiled FPC binaries: the host's binutils strip differs from the target's; always use the <target>-objcopy and <target>-strip from the cross toolchain, never the host versions.

scripts/delphi-build.ps1 passes -GD when -Compiler dcc64 is selected and Config != Release-Stripped; scripts/fpc-build.sh passes -gw3 -gl by default. See references/reading-stack-traces.md for the symbol-resolution toolchain (mORMot built-in, addr2line, Map2DWARF on Delphi for Lazarus interop).

5. Read FastMM4 / fpcx64mm leak reports

A leak at shutdown reaches you as a multi-line text dump. The FastMM4 (Delphi) and mormot.core.fpcx64mm (FPC) versions share the same shape: a count, a per-allocation size class, and (when FullDebugMode / FPCMM_DEBUG is on) a stack trace per allocation:

This application has leaked memory. The small block leaks are
(excluding any internal expected leaks of the memory manager):

5 - 12 bytes: TStringBuilder x 2, UnicodeString x 1
121 - 132 bytes: TMyService x 1
   Stack trace of leak:
     0x00007FF6C123ABCD mymain.pas TMyService.Create (line 87)
     0x00007FF6C123CDEF mymain.pas WireUp (line 142)

Reading the report:

1. Count and size — TMyService x 1 at 121-132 bytes means one instance of an object whose size lands in the [121,132] block size. Match against SizeOf(TMyService) + class header (16 B on 64-bit).
2. Stack trace — only present in FullDebugMode (Delphi FastMM4) or with -dFPCMM_DEBUG -dFPCMM_FULLDEBUG (FPC fpcx64mm). Without these, you see only the count and the class name (RTTI-derived).
3. False positives — finalization-order leaks of mORMot global singletons (TRestOrmCache.Done running before TRttiCustom.Done) are tracked as expected leaks; the manager subtracts them. Real false positives come from dynamic packages (BPLs/SO that unload before the manager checks) and from string interning (mormot.core.text.UniqueRawUtf8 keeps a global hash table).

scripts/delphi-build.ps1 -Config Debug enables FullDebugMode; scripts/fpc-build.sh --debug enables FPCMM_DEBUG. See references/fastmm4-leaks.md for false-positive triage and the full "what the bytes mean" decoder.

6. Map a raw address to a source line

When the log says $00007FF6C123ABCD and nothing else, mORMot's parser failed to find symbols. Three resolvers, in order of preference:

// Delphi .map already loaded at startup:
TDebugFile.FindLocation(addr) -> 'mymain.pas (123)'

// FPC DWARF (requires -gw3 -gl):
GetCallerAddr(addr) -> 'mymain.pas (123)'

// Last resort, external tool:
//   addr2line -e myserver.exe -f -i 0x401abc       (FPC, GNU binutils)
//   Map2DWARF myserver.map myserver.dwarf          (Delphi -> FPC tooling)

The most common cause of "no symbols" is a .map next to the source tree but not next to the deployed binary. Always copy .map together with .exe in your release archive; on FPC, prefer the embedded DWARF path so there is nothing extra to copy. See references/reading-stack-traces.md for offsets, ASLR adjustments, and how to handle stripped binaries with split .dbg files.

Common pitfalls

• .map not deployed alongside .exe. Delphi releases routinely ship the binary without the map; the resulting log shows raw hex addresses and nobody can resolve them after the fact. Either include myserver.map in the release archive (it's small, gzip-friendly), or build with FPC + DWARF where the symbols travel inside the binary. Verify on a clean machine before shipping: copy .exe only, run, raise an exception, confirm the log resolves the stack frame.
• Family.Level := LOG_VERBOSE left in production. Verbose logs include sllEnter / sllLeave for every instrumented method; on a busy server that is gigabytes per hour and a measurable throughput hit. Use LOG_NFO (info + warning + error + monitoring) as the production default; promote to LOG_VERBOSE only inside an if SomeDebugMode then ... else gate, or by SIGUSR1-style reload.
• FastMM4 false positive on dynamic packages. A .bpl that registers a TPersistent descendant and then unloads before FastMM4 reports leaks looks like a 121-132 bytes: TMyClass x 1 leak with no stack trace. Either keep the package loaded for the lifetime of the host (LoadPackage without UnloadPackage), or call RegisterExpectedMemoryLeak from the package's Initialization for each registered class.
• Logger thread contention on a hot path. A single global log file with PerThreadLog := ptIdentifiedInOneFile serializes writes through one mutex; under heavy contention you can see sllInfo calls take 50+ microseconds because they're queued. Either switch to ptOneFilePerThread (one file per thread, no contention but harder to read), reduce Level so fewer lines compete, or raise BufferSize (default 8 KB) so flushes are less frequent.
• HandleExceptions := true and a noisy library. Enabling exception interception on a project that uses Indy or any TCP library that raises on disconnect (EIdConnClosedGracefully, EIdSocketError) floods the log. Add the noisy classes to Family.ExceptionIgnore, set ExceptionIgnoreLibrary := true to skip exceptions raised from inside loaded .bpl / .so files, or set ExceptionIgnoreCurrentThread := true around the noisy worker for the duration of its run.
• Log file not closed on shutdown. A program that aborts (Halt, signal) without running unit finalization can leave the in-memory BufferSize worth of log entries unwritten. The very last few seconds before a crash are exactly the lines you need. Set AutoFlushTimeOut := 1 (seconds) on a debug build so the background thread flushes continuously, and call TSynLog.Family.SynLog.Flush explicitly at the end of your try/finally shutdown path.
• DWARF level too low (-g only). FPC -g (or -gl) without -gw3 produces stabs-format debug info, which mORMot's resolver does not parse. Symptom: stack traces show addresses, no source lines, and objdump --debugging reports stabs. Always pair -gw3 (DWARF v3) with -gl (line numbers) for mORMot compatibility; older Lazarus IDE templates default to -g only.
• HighResolutionTimestamp := true with rotation. The high-resolution timestamp is calibrated once at file open and stored in the file header; switching files mid-process (rotation, daily roll) invalidates the calibration for the new file. Either turn on rotation OR high-resolution timestamps, not both. The compiler does not warn; Family.SetEchoToConsole will fail silently when both are set.
• Stripped FPC binary with DWARF still expected. A release build run through strip --all removes both the symbol table and the DWARF section. mORMot's resolver then walks the binary, finds nothing, and falls back to raw hex. Use objcopy --only-keep-debug myserver myserver.dbg && strip --strip-debug myserver && objcopy --add-gnu-debuglink=myserver.dbg myserver so the stripped binary points at the side-loaded debug file; ship the .dbg to the support team but not necessarily to end users.

See also

• $MORMOT2_DOC_PATH/mORMot2-SAD-Chapter-25.md - Testing and Logging (the authoritative chapter on TSynLog)
• references/tsynlog-setup.md - per-environment configuration recipes for TSynLogFamily
• references/fastmm4-leaks.md - reading FastMM4 / fpcx64mm leak reports and triaging false positives
• references/reading-stack-traces.md - building with .map / DWARF and resolving raw addresses
• test-driven-development for writing the test that causes the log line you are reading
• systematic-debugging for the four-phase Capture/Reproduce/Bisect/Fix workflow that drives this skill's instruments
• delphi-build and fpc-build for the compile-time flags (-GD, -gw3 -gl) that make stack traces resolvable
• mormot2-core for RawUtf8, conditional defines, and the unit conventions every snippet above leans on
• mormot2-deploy for log file location, rotation policy, and shipping to a SIEM in production