nupp.log

nupp.log is leveled logging whose disabled path is the one it is designed around. A severity call in statement position is lowered rather than called, so a filtered line evaluates none of its arguments.

nupp.log.error("cannot open %s: %s", path, reason)
nupp.log.warn("retrying in %dms", delay)
nupp.log.info("loaded %d entities", count)
nupp.log.debug("state=%s", state)

Each severity accepts a string.format directive string and the arguments it calls for. The directives and their argument types are checked where the call is written, by the same machinery that checks string.format, so a missing argument or a %d handed a string is a compile error rather than a line that fails at run time.

nupp.log.error("id %d")
  error: NUPP2006: omitted argument 2 supplies nil, not number

Because %s accepts anything, nothing needs tostring and a nil argument prints as nil rather than raising. Lines go to standard error until a host says otherwise.

%? is Nupp's debug directive. It requires nupp.Debug, calls the value's debug() method, and formats the returned string as %s:

nupp.log.debug("state=%?", state)

At lowered call sites that method call is inside the level guard, so filtered logs do not render the value. Named loggers perform the same check in their already-lazy writer.

Severity calls are intrinsics#

A severity call in statement position whose format is a literal is lowered rather than called:

nupp.log.error("id %d", id)

const __nuppModule = require("nupp.log").forModule("amb");   -- once, in the prologue
if __nuppModule.on[1] then __nuppModule.emit(1,47,string.format("id %d",id)) end

Three properties follow from that shape, and together they are the reason this is a compiler intrinsic rather than a library.

Filtered calls evaluate nothing#

The level test stands at the call site, so the arguments of a suppressed line are never computed. nupp.log.debug("%s", render(state)) does not call render when debug is off. No library can decline to evaluate its own arguments.

Module name and line are constants#

The compiler is generating the file, so it writes both in directly: the module once in the prologue, the line at each site. Nothing is recovered at run time, nothing depends on the debug library, and there is no per-module boilerplate to write or to keep in step with a rename.

Filtered call cost#

A filtered call costs an upvalue read, an array index and a branch. The view is bound once per module, and on is an array indexed by severity, shared with every other module so a level change is seen everywhere at once.

Forms that stay calls#

Every other form keeps an ordinary call meaning exactly the same thing, only slower. The module shows as ?, and the arguments are evaluated:

Levels#

level reads the threshold and setLevel moves it:

nupp.log.setLevel("debug") -- returns the previous one
nupp.log.level() -- "debug"

The five levels are "off", "error", "warn", "info" and "debug", each admitting itself and everything above it, so "warn" emits warnings and errors. The default is "warn".

The parameter is that literal union, so a string from outside the program has to be narrowed to one of the five before it can be passed. os.getenv("LOG_LEVEL") or "warn" is string, and string is not one of them:

local wanted = os.getenv("LOG_LEVEL")
if wanted == "debug" or wanted == "info" or wanted == "warn" then
    nupp.log.setLevel(wanted)
end

A level that is not one of the five is a compile error where it is a literal and an ordinary raise where it is not.

nupp.log.enabled(level) returns whether a level would emit. Use it to guard preparation spanning more than one call, which no single lowered site can elide:

if nupp.log.enabled("debug") then
    local report = summarize(world)
    nupp.log.debug("world: %s", report)
end

Module levels#

setModuleLevel overrides the threshold for one exact module name. Modules without an override inherit the global threshold, including after it changes:

nupp.log.setLevel("warn")
nupp.log.setModuleLevel("game.physics", "debug")

The override reaches existing and future module views. moduleLevel reads the effective threshold, and passing "inherit" removes the override:

nupp.log.moduleLevel("game.physics") -- "debug"
nupp.log.setModuleLevel("game.physics", "inherit") -- restore the global threshold

Names are exact: configuring game.physics does not also configure game.physics.collision. A named logger with the same name uses the same threshold.

Swapping the back end#

A host that logs through its own facility installs a sink function and takes over completely. It receives the parts, not a rendered line, and pays for no formatting it would discard:

nupp.log.setSink(function(level: integer, module: string, line: integer, message: string): nil
    sdl.logMessage(CATEGORY, PRIORITY[level], ("%s:%d %s"):format(module, line, message))
end)

level is 1 error, 2 warn, 3 info, 4 debug; nupp.log.levelName turns one back into its name. line is 0 for a line the compiler could not attribute, which is every line from a named logger.

Passing anything file-like instead keeps the built-in rendering and only moves where it goes:

nupp.log.setSink(assert(io.open("game.log", "a")))

io.open returns LuaFile?, and setSink takes a target rather than a maybe, so the assert is what turns one into the other. The target is taken: the log owns it from then on, and sink() reads which one is in force.

A file-like target renders through the formatter, which is replaceable on its own:

nupp.log.setFormatter(function(level: integer, module: string, line: integer, message: string, stamp: string): string
    return ("%s[%s] %s"):format(stamp, nupp.log.levelName(level), message)
end)

Both setters return the value they replaced, so a host can restore what it found, and setFormatter(nil) returns to the built-in rendering.

Timestamps#

nupp.log.timestamp() returns the current time formatted, recomputed at most once per wall-clock second and shared by every logger. It is a pull rather than something pushed to sinks, so a host that stamps its own lines never pays for one.

nupp.log.setTimestampFormat("%H:%M:%S ") -- returns the previous format
nupp.log.setTimestampFormat("") -- off
nupp.log.timestampFormat() -- ""

Named loggers#

named returns a logger carrying a fixed name, with a method per severity:

local physics = nupp.log.named("physics")
physics:warn("step %d took %.2fms", step, elapsed)

Use one for a subsystem that does not correspond to a module, and for a call site the intrinsic cannot reach. Repeating a name returns the same logger. Their methods are replaced when the level or target changes, so a filtered call reaches an empty function rather than a test, but the arguments are still evaluated, which is the cost of a name chosen at run time.

Cost#

The installer lands only in modules that reach nupp.log, like every other compiler-provided facility. A module that never logs carries nothing.

type log.Formatter = function(
    level: log.Severity,
    module: string,
    line: integer,
    message: string,
    stamp: string
): string

type log.Level = "off" | "error" | "warn" | "info" | "debug"

type log.LevelOverride = log.Level | "inherit"

record log.Logger ...

name: string

debug: function<F is string>(self: log.Logger, fmt: F, ...: unpackof __NuppFormatArguments(F, nupp.Debug)): nil

info: function<F is string>(self: log.Logger, fmt: F, ...: unpackof __NuppFormatArguments(F, nupp.Debug)): nil

warn: function<F is string>(self: log.Logger, fmt: F, ...: unpackof __NuppFormatArguments(F, nupp.Debug)): nil

error: function<F is string>(self: log.Logger, fmt: F, ...: unpackof __NuppFormatArguments(F, nupp.Debug)): nil

enabled: function(self: log.Logger, level: log.Level): boolean

type log.Severity = integer

type log.Sink = function(level: log.Severity, module: string, line: integer, message: string): nil

type log.Target = log.Sink | LuaFile

function log.debug<F is string>(fmt: F, ...: unpackof __NuppFormatArguments(F, nupp.Debug)): nil

function log.enabled(level: log.Level): boolean

function log.error<F is string>(fmt: F, ...: unpackof __NuppFormatArguments(F, nupp.Debug)): nil

function log.formatter(): log.Formatter?

function log.info<F is string>(fmt: F, ...: unpackof __NuppFormatArguments(F, nupp.Debug)): nil

function log.level(): log.Level

function log.levelName(severity: log.Severity): log.Level

function log.moduleLevel(name: string): log.Level

function log.named(name: string): log.Logger

const log = nupp.log.named("renderer")
log:info("loaded %d entities", count)

function log.setFormatter(next: log.Formatter?): log.Formatter?

function log.setLevel(level: log.Level): log.Level

function log.setModuleLevel(name: string, level: log.LevelOverride): log.Level

function log.setSink(takes next: log.Target): log.Target

function log.setTimestampFormat(next: string): string

function log.sink(): log.Target

function log.timestamp(): string

function log.timestampFormat(): string

function log.warn<F is string>(fmt: F, ...: unpackof __NuppFormatArguments(F, nupp.Debug)): nil