jdb
46245b3f1e
Use getTime().utc in both message constructors, document the timezone change, and cover concurrent construction and structured formatting. Restore ordinary logging calls in the parallel writer fixture. Validation: 32 unit tests and 29 regression tests pass. Timestamp sanitizer checks pass under UTC and non-UTC timezones. The full suite retains the known allocator reports in factory-state and allocator.
272 lines
9.8 KiB
Nim
272 lines
9.8 KiB
Nim
import std/[json, os, osproc, strutils, tempfiles, times, unittest]
|
|
import ../src/namespaced_logging
|
|
import ./ownership
|
|
|
|
suite "Log message timestamps":
|
|
test "both constructors capture the current instant in UTC":
|
|
let before = getTime()
|
|
let textMessage = initLogMessage("timestamp", lvlInfo, "text")
|
|
let jsonMessage = initLogMessage("timestamp", lvlInfo, %*{"msg": "json"})
|
|
let after = getTime()
|
|
for message in [textMessage, jsonMessage]:
|
|
check message.ts.timezone.name == "Etc/UTC"
|
|
check message.ts.utcOffset == 0
|
|
check not message.ts.isDst
|
|
check message.ts.toTime >= before
|
|
check message.ts.toTime <= after
|
|
|
|
test "structured output represents generated timestamps in UTC":
|
|
for message in [initLogMessage("timestamp", lvlInfo, "text"),
|
|
initLogMessage("timestamp", lvlInfo, %*{"msg": "json"})]:
|
|
let encoded = parseJson(formatJsonStructuredLog(message))["ts"].getStr
|
|
check encoded == message.ts.format("yyyy-MM-dd'T'HH:mm:sszzz")
|
|
check encoded.endsWith("Z")
|
|
|
|
type
|
|
CloneControl = object
|
|
failNext: bool
|
|
FallibleAppender = ref object of LogAppender
|
|
control: ptr CloneControl
|
|
|
|
method clone(app: FallibleAppender): LogAppender {.gcsafe.} =
|
|
if app.control.failNext:
|
|
app.control.failNext = false
|
|
raise newException(ValueError, "injected clone failure")
|
|
FallibleAppender(control: app.control)
|
|
|
|
type
|
|
RefreshProbeObj = object of LogAppender
|
|
destroyed: ptr int
|
|
RefreshProbe = ref RefreshProbeObj
|
|
|
|
proc `=destroy`(app: RefreshProbeObj) =
|
|
if app.destroyed != nil: inc app.destroyed[]
|
|
`=destroy`(app.namespace)
|
|
|
|
method clone(app: RefreshProbe): LogAppender {.gcsafe.} =
|
|
RefreshProbe(namespace: app.namespace, destroyed: app.destroyed)
|
|
|
|
type
|
|
LifetimeProbeObj = object
|
|
destroyed: ptr int
|
|
LifetimeProbe = SharedLogState[LifetimeProbeObj]
|
|
|
|
proc `=destroy`(probe: LifetimeProbeObj) =
|
|
if probe.destroyed != nil:
|
|
inc probe.destroyed[]
|
|
|
|
proc ignoreMessage(state: var LifetimeProbe, msg: LogMessage) {.gcsafe, noconv.} =
|
|
discard
|
|
|
|
proc watchedService(destroyed: ptr int, namespace = ""): LogService =
|
|
result = initLogService()
|
|
result.addAppender(initCustomLogAppender(
|
|
initSharedLogState(LifetimeProbeObj(destroyed: destroyed)), ignoreMessage,
|
|
namespace = namespace))
|
|
|
|
proc createAndReleaseService(destroyed: ptr int) =
|
|
var service = watchedService(destroyed)
|
|
service.setThreshold("worker", lvlInfo)
|
|
# All owning handles leave scope here. No thread or cycle is involved.
|
|
|
|
suite "ORC service handle lifetime":
|
|
test "copy, self-assignment, replacement, and move retain exactly one lifetime":
|
|
var firstDestroyed, replacedDestroyed = 0
|
|
block:
|
|
var first = watchedService(addr firstDestroyed)
|
|
var other = watchedService(addr replacedDestroyed)
|
|
other = first
|
|
check replacedDestroyed == 1
|
|
first = first
|
|
first = LogService()
|
|
check firstDestroyed == 0
|
|
|
|
var moved = move(other)
|
|
expect ValueError:
|
|
discard other.threadLocalRef()
|
|
moved.setThreshold("worker", lvlInfo)
|
|
let local = moved.threadLocalRef()
|
|
moved = LogService()
|
|
check firstDestroyed == 0
|
|
check local.getLogger("worker").isEnabled(lvlInfo)
|
|
check firstDestroyed == 1
|
|
check replacedDestroyed == 1
|
|
|
|
test "handles embedded in copied containers retain the service":
|
|
var destroyed = 0
|
|
block:
|
|
var source = watchedService(addr destroyed)
|
|
var handles = @[source, source]
|
|
var copied = handles
|
|
source = LogService()
|
|
handles.setLen(0)
|
|
check destroyed == 0
|
|
copied[0].setThreshold("worker", lvlWarn)
|
|
let local = copied[1].threadLocalRef()
|
|
check not local.getLogger("worker").isEnabled(lvlInfo)
|
|
copied.setLen(0)
|
|
check destroyed == 0
|
|
check destroyed == 1
|
|
|
|
test "an exported handle outlives the local service it came from":
|
|
var destroyed = 0
|
|
block:
|
|
var exported: LogService
|
|
block:
|
|
let local = watchedService(addr destroyed).threadLocalRef()
|
|
exported = local.service
|
|
check destroyed == 0
|
|
check exported.threadLocalRef().getLogger("worker").isEnabled(lvlInfo)
|
|
check destroyed == 1
|
|
|
|
test "failed local construction releases its shared owner and partial cache":
|
|
var destroyed = 0
|
|
var control: CloneControl
|
|
block:
|
|
var service = watchedService(addr destroyed)
|
|
service.addAppender(FallibleAppender(control: addr control))
|
|
control.failNext = true
|
|
expect ValueError:
|
|
discard service.threadLocalRef()
|
|
check destroyed == 0
|
|
check destroyed == 1
|
|
|
|
suite "ORC ownership and configuration regressions":
|
|
test "isEnabled uses cached namespace thresholds until a refresh":
|
|
var service = initLogService()
|
|
service.setThreshold("worker", lvlError)
|
|
let local = service.threadLocalRef()
|
|
let logger = local.getLogger("worker")
|
|
check not logger.isEnabled(lvlInfo)
|
|
|
|
# Simulate a change from another service handle without introducing a
|
|
# reference-count race into this deterministic configuration test.
|
|
service.setThreshold("worker", lvlInfo)
|
|
check not logger.isEnabled(lvlInfo)
|
|
|
|
local.ensureFreshness()
|
|
check logger.isEnabled(lvlInfo)
|
|
|
|
# A stale true result can become false when the logging call refreshes.
|
|
service.setThreshold("worker", lvlError)
|
|
check logger.isEnabled(lvlInfo)
|
|
logger.info("filtered after refreshing configuration")
|
|
check not logger.isEnabled(lvlInfo)
|
|
|
|
# Creating another logger also refreshes their shared local service.
|
|
service.setThreshold("worker", lvlInfo)
|
|
check not logger.isEnabled(lvlInfo)
|
|
discard local.getLogger("another")
|
|
check logger.isEnabled(lvlInfo)
|
|
|
|
test "isEnabled reads the shared root fallback without refreshing namespaces":
|
|
var service = initLogService(rootLevel = lvlError)
|
|
let local = service.threadLocalRef()
|
|
let logger = local.getLogger("worker")
|
|
check not logger.isEnabled(lvlInfo)
|
|
|
|
service.setRootThreshold(lvlInfo)
|
|
service.setThreshold("worker", lvlError)
|
|
check logger.isEnabled(lvlInfo)
|
|
local.ensureFreshness()
|
|
check not logger.isEnabled(lvlInfo)
|
|
|
|
test "a failed refresh is retried without another configuration change":
|
|
var control: CloneControl
|
|
var service = initLogService()
|
|
service.addAppender(FallibleAppender(control: addr control))
|
|
let local = service.threadLocalRef()
|
|
discard local.getLogger("worker")
|
|
service.setRootThreshold(lvlInfo)
|
|
|
|
control.failNext = true
|
|
expect ValueError:
|
|
local.ensureFreshness()
|
|
|
|
# clone now succeeds; the failed refresh must not have marked the
|
|
# incomplete local configuration as current.
|
|
local.ensureFreshness()
|
|
check local.appenders().len == 1
|
|
|
|
test "failed refresh preserves the old cache and releases partial replacements":
|
|
var oldStateDestroyed, discardedClones: int
|
|
var control: CloneControl
|
|
var service = watchedService(addr oldStateDestroyed, "old")
|
|
service.setThreshold("worker", lvlError)
|
|
let local = service.threadLocalRef()
|
|
let logger = local.getLogger("worker")
|
|
|
|
# Only the local cache retains the old appender's state after this change.
|
|
service.clearAppenders()
|
|
service.addAppender(RefreshProbe(namespace: "new", destroyed: addr discardedClones))
|
|
service.addAppender(FallibleAppender(control: addr control))
|
|
service.setThreshold("worker", lvlInfo)
|
|
let initiallyDestroyed = discardedClones
|
|
|
|
for attempt in 1 .. 2:
|
|
control.failNext = true
|
|
expect ValueError:
|
|
local.ensureFreshness()
|
|
check oldStateDestroyed == 0
|
|
check discardedClones == initiallyDestroyed + attempt
|
|
block:
|
|
let cached = local.appenders()
|
|
require cached.len == 1
|
|
check cached[0].namespace == "old"
|
|
check not logger.isEnabled(lvlInfo)
|
|
|
|
# No further configuration update is needed to retry and install both
|
|
# the new appenders and the new namespace thresholds.
|
|
local.ensureFreshness()
|
|
check oldStateDestroyed == 1
|
|
let cached = local.appenders()
|
|
require cached.len == 2
|
|
check cached[0].namespace == "new"
|
|
check logger.isEnabled(lvlInfo)
|
|
|
|
test "releasing the service releases state owned by its appenders":
|
|
var destroyed = 0
|
|
createAndReleaseService(addr destroyed)
|
|
check destroyed == 1
|
|
|
|
suite "Background writer shutdown regressions":
|
|
for destination in ["file", "console", "stderr", "file-empty", "console-empty",
|
|
"files", "file-parallel", "console-parallel"]:
|
|
test destination & " writer drains accepted messages at normal process exit":
|
|
let directory = createTempDir("namespaced_logging_shutdown_", "")
|
|
let outputPath = directory / "messages.log"
|
|
defer: removeDir(directory)
|
|
|
|
let child = startProcess(parentDir(getAppFilename()) / "writer_child",
|
|
args = [destination, outputPath], options = {poParentStreams})
|
|
defer: close(child)
|
|
let exitCode = child.waitForExit(15_000)
|
|
if exitCode == -1:
|
|
child.kill()
|
|
discard child.waitForExit()
|
|
check exitCode == 0
|
|
require fileExists(outputPath)
|
|
|
|
if destination.endsWith("-parallel"):
|
|
let received = readFile(outputPath).splitLines()
|
|
require received.len == 10_001
|
|
var next = [0, 2_500, 5_000, 7_500]
|
|
for line in received[0 ..< 10_000]:
|
|
require line.startsWith("message ")
|
|
let number = parseInt(line[8 .. ^1])
|
|
require number in 0 ..< 10_000
|
|
let worker = number div 2_500
|
|
check number == next[worker]
|
|
inc next[worker]
|
|
check next == [2_500, 5_000, 7_500, 10_000]
|
|
else:
|
|
var expected: string
|
|
for i in 0 ..< 10_000:
|
|
if destination == "file-empty" and i mod 128 == 0:
|
|
expected.add("\n")
|
|
expected.add("message " & $i & "\n")
|
|
check readFile(outputPath) == expected
|
|
if destination == "files":
|
|
require fileExists(outputPath & ".second")
|
|
check readFile(outputPath & ".second") == expected
|