nsmcp::CachedLogSearch method errorSummary (public)

 <instance of nsmcp::CachedLogSearch> errorSummary options \
    redactor

Defined in /usr/local/ns/tcl/nsmcp/log-summary.tcl

Parameters:

options (required)

redactor (required)

Testcases:

No testcase defined.

Source code:

set from [dict get $options from]
set to [dict get $options to]
set maxGroups [dict get $options maxGroups]
set severities [expr {[dict exists $options severities] ? [dict get $options severities] : {Error Fatal Bug}}]
file stat ${:path} before
set source [open ${:path} rb]
set groups {}
set matched 0
set ungrouped 0
set unknownTime 0
set unrecognized 0
set examples {}
set timestampedRecords 0
set earliestAt {}
set latestAt {}
set firstEntryAt {}
set lastEntryAt {}
set firstEntryOffset {}
set lastEntryOffset {}
set cachedStamp {}
set cachedSeconds {}
set postgresRecords 0
set postgresExamples {}
set previousTimestamp {}
set pendingPostgres {}
set mutexTraces 0
set mutexGroups {}
set mutexUngrouped 0
set shortEntries 0
set untimestamped 0
set untimestampedExamples {}
set severityTotals {}; set unknownTimeTotals {}
foreach severity $severities {dict set severityTotals $severity 0; dict set unknownTimeTotals $severity 0}
set pending false
set clipped 0
set firstTime {}
set lastTime {}
set deadline [expr {[clock milliseconds]+1000}]
set start 0
set examined 0
set stable true
set prefix {}
if {[dict exists $options scanState]} {
    set state [dict get $options scanState]
    foreach name {groups matched ungrouped unknownTime unrecognized examples severityTotals unknownTimeTotals pending clipped firstTime lastTime start examined prefix mutexTraces mutexGroups mutexUngrouped shortEntries untimestamped untimestampedExamples postgresRecords postgresExamples previousTimestamp pendingPostgres timestampedRecords earliestAt latestAt firstEntryAt lastEntryAt firstEntryOffset lastEntryOffset cachedStamp cachedSeconds} {
        if {[dict exists $state $name]} {set $name [dict get $state $name]}
    }
    if {![dict exists $state mutexGroups]} {set mutexUngrouped $mutexTraces}
    if {[list $before(dev) $before(ino)] ne [dict get $state identity]
        || $before(size) < [dict get $state sourceBytes]} {
        close $source
        error "system log changed during summary scan; start a new summary"
    }
    set before(size) [dict get $state sourceBytes]
}
set chunkEnd [expr {min($before(size),$examined+4194304)}]
set reader {}
try {
    set currentPrefix [read $source [expr {min(256,$before(size))}]]
    if {$prefix ne "" && $prefix ne $currentPrefix} {
        error "system log changed during summary scan; start a new summary"
    }
    set prefix $currentPrefix
    seek $source $examined
    set reader [::nsmcp::LogSummaryReader new -channel $source -limit $before(size) -offset $examined -maxBytes ${:maxMessageBytes}]
    while {$examined < $chunkEnd && [clock milliseconds] < $deadline} {
        set offset $examined
        set event [$reader next]
        set examined [dict get $event endOffset]
        if {$examined <= $offset} {break}
        if {![dict get $event complete]} {set pending true}
        # Neighboring timestamp strings are contextual estimates, never dates
        # assigned to the diagnostic or used for time-window error totals.
        if {[regexp {^\[([0-9]{2}/[A-Za-z]{3}/[0-9]{4}:[^\]\r\n]+)\]\[[^\]]+\]\[[^\]]+\]} [dict get $event message] -> stamp]} {
            if {$stamp ne $cachedStamp} {
                set cachedStamp $stamp
                set cachedSeconds [${:recordParser} timestampSeconds $stamp]
            }
            if {$cachedSeconds ne ""} {
                incr timestampedRecords
                if {$firstEntryAt eq ""} {set firstEntryAt $cachedSeconds; set firstEntryOffset $offset}
                set lastEntryAt $cachedSeconds
                set lastEntryOffset $offset
                if {$earliestAt eq "" || $cachedSeconds<$earliestAt} {set earliestAt $cachedSeconds}
                if {$latestAt eq "" || $cachedSeconds>$latestAt} {set latestAt $cachedSeconds}
            }
            foreach i $pendingPostgres {
                set fields [lindex $postgresExamples $i]
                lappend fields followingTimestamp string $stamp
                lset postgresExamples $i $fields
            }
            set pendingPostgres {}
            set previousTimestamp $stamp
        }
        # Most records are Notice/Debug output. Avoid parser dispatch and
        # metadata allocation for valid headers outside the counted levels.
        if {[regexp {^\[[^\]\r\n]+\]\[[^\]\r\n]+\]\[[^\]\r\n]+\][ \t]+([A-Za-z][A-Za-z0-9_()-]*):[ \t]*} [dict get $event message] -> level]
            && $level ni $severities} {continue}
        set meta [${:recordParser} metadata [dict get $event message]]
        set recordType [dict get $meta recordType]
        if {$recordType eq "postgres"} {
            incr postgresRecords
            if {[llength $postgresExamples]<5} {
                set text [$redactor message [dict get $event message]]
                lappend pendingPostgres [llength $postgresExamples]
                lappend postgresExamples [list offset number $offset endOffset number $examined  severity string [dict get $meta severity] example string [string range $text 0 511]  truncated boolean [expr {[dict get $event truncated] || [string length $text]>512}]  timeSource string inferred-neighbors precedingTimestamp string $previousTimestamp]
            }
        }
        if {$recordType eq "mutex-trace"} {
            # Scheduler condition waits are expected implementation details,
            # not contention evidence. Exclude only this exact hold trace;
            # ns:sched lock waits and negative-wait warnings remain visible.
            if {[dict get $meta mutexName] eq "ns:sched"
                && [dict get $meta mutexOperation] eq "unlock"
                && [dict get $meta mutexMetric] eq "hold"} {continue}
            incr mutexTraces
            set mutexKey [list [dict get $meta mutexName] [dict get $meta mutexOperation] [dict get $meta mutexMetric]]
            set duration [dict get $meta mutexDurationSeconds]
            if {[dict exists $mutexGroups $mutexKey]} {
                set group [dict get $mutexGroups $mutexKey]
                dict incr group count
                dict set group total [expr {[dict get $group total]+$duration}]
                dict set group min [expr {min([dict get $group min],$duration)}]
                dict set group lastOffset $offset
                if {$duration > [dict get $group max]} {
                    dict set group max $duration
                    dict set group maxOffset $offset
                    dict set group maxThread [$redactor message [dict get $meta logThread]]
                }
                if {$duration<0} {dict incr group negative}
                dict set mutexGroups $mutexKey $group
            } elseif {[dict size $mutexGroups]<128} {
                dict set mutexGroups $mutexKey [dict create count 1 total $duration min $duration max $duration  firstOffset $offset lastOffset $offset maxOffset $offset  maxThread [$redactor message [dict get $meta logThread]] negative [expr {$duration<0}]]
            } else {
                incr mutexUngrouped
            }
        }
        if {$recordType eq "system-short"} {incr shortEntries}
        if {$recordType in {mutex-trace system-short postgres}} {
            incr untimestamped
            if {[llength $untimestampedExamples]<5} {
                set text [$redactor message [dict get $event message]]
                set fields [list offset number $offset endOffset number $examined  recordType string $recordType logThread string [dict get $meta logThread]  severity string [dict get $meta severity] example string [string range $text 0 511]  truncated boolean [expr {[dict get $event truncated] || [string length $text]>512}]]
                foreach key {mutexName mutexOperation mutexMetric} {
                    if {[dict exists $meta $key]} {lappend fields $key string [$redactor message [dict get $meta $key]]}
                }
                if {[dict exists $meta mutexDurationSeconds]} {
                    lappend fields mutexDurationSeconds number [dict get $meta mutexDurationSeconds]
                }
                lappend untimestampedExamples $fields
            }
        }
        if {$recordType eq "mutex-trace"} {continue}
        set severity [dict get $meta severity]
        if {$severity eq ""} {
            incr unrecognized
            if {[llength $examples] < 5} {
                lappend examples [list offset number $offset endOffset number $examined  example string [string range [$redactor message [dict get $event message]] 0 511]  truncated boolean [expr {[dict get $event truncated] || [string length [dict get $event message]]>512}]]
            }
            continue
        }
        if {$severity ni $severities} {continue}
        set timestamp [dict get $meta timestamp]
        if {$timestamp eq $cachedStamp} {
            set seconds $cachedSeconds
        } else {
            set seconds [${:recordParser} timestampSeconds $timestamp]
        }
        if {$seconds eq "" || ![string is double -strict $seconds]} {
            if {$severity in {Error Fatal Bug}} {incr unknownTime}
            dict incr unknownTimeTotals $severity
            continue
        }
        if {$seconds < $from || $seconds >= $to} {continue}
        incr matched
        dict incr severityTotals $severity
        if {$firstTime eq "" || $seconds < $firstTime} {set firstTime $seconds}
        if {$lastTime eq "" || $seconds > $lastTime} {set lastTime $seconds}
        set text [$redactor message [dict get $event message]]
        # Group by redacted first-line text, normalizing numeric tokens and
        # addresses in hex. Full examples retain their original values.
        set heading [lindex [split $text \n] 0]
        regsub {^\[[^\]]+\]\[[^\]]+\]\[[^\]]+\][ \t]+[A-Za-z]+:[ \t]*} $heading {} heading
        set pattern [string range $heading 0 511]
        regsub -all {0x[0-9A-Fa-f]+} $pattern {<hex>} pattern
        regsub -all {\m[0-9]+\M} $pattern {<n>} pattern
        set key [list $severity $pattern]
        if {![dict exists $groups $key]} {
            if {[dict size $groups] >= $maxGroups} {incr ungrouped; continue}
            dict set groups $key [dict create severity $severity pattern $pattern count 0  firstAt $seconds lastAt $seconds example [string range $text 0 2047]  requestIdentifier [dict get $meta requestIdentifier] exampleTruncated false]
        }
        set group [dict get $groups $key]
        dict incr group count
        dict set group firstAt [expr {min([dict get $group firstAt],$seconds)}]
        dict set group lastAt [expr {max([dict get $group lastAt],$seconds)}]
        if {[dict get $event truncated] || [string length $text]>2048} {
            dict set group exampleTruncated true
            incr clipped
        }
        dict set groups $key $group
    }
    file stat ${:path} after
    seek $source 0
    set stable [expr {[list $before(dev) $before(ino)] eq [list $after(dev) $after(ino)]  && $after(size)>=$before(size) && [read $source [string length $prefix]] eq $prefix}]
} finally {
    if {$reader ne ""} {$reader destroy}
    close $source
}
if {!$stable} {error "system log changed during summary scan; start a new summary"}
set state {}
if {$examined < $before(size)} {
    foreach name {groups matched ungrouped unknownTime unrecognized examples severityTotals unknownTimeTotals pending clipped firstTime lastTime start examined prefix mutexTraces mutexGroups mutexUngrouped shortEntries untimestamped untimestampedExamples postgresRecords postgresExamples previousTimestamp pendingPostgres timestampedRecords earliestAt latestAt firstEntryAt lastEntryAt firstEntryOffset lastEntryOffset cachedStamp cachedSeconds} {
        dict set state $name [set $name]
    }
    dict set state identity [list $before(dev) $before(ino)]
    dict set state sourceBytes $before(size)
}
set exampleEntries {}
set i 0
foreach example $examples {lappend exampleEntries $i object $example; incr i}
set untimestampedEntries {}
set i 0
foreach example $untimestampedExamples {
    lappend untimestampedEntries $i object $example
    incr i
}
set mutexEntries {}; set i 0
dict for {key group} $mutexGroups {
    lassign $key mutex operation metric
    lappend mutexEntries $i object [list mutexName string [$redactor message $mutex]  operation string $operation metric string $metric count number [dict get $group count]  minSeconds number [dict get $group min] maxSeconds number [dict get $group max]  meanSeconds number [expr {[dict get $group total]/double([dict get $group count])}]  negativeDurations number [dict get $group negative]  firstOffset number [dict get $group firstOffset] lastOffset number [dict get $group lastOffset]  maxOffset number [dict get $group maxOffset] maxLogThread string [dict get $group maxThread]]
    incr i
}
set postgresEntries {}
set i 0
foreach example $postgresExamples {
    if {[lsearch -exact $example followingTimestamp]<0} {lappend example followingTimestamp string {}}
    lappend postgresEntries $i object $example
    incr i
}
set severityFields {}
dict for {severity count} $severityTotals {lappend severityFields $severity number $count}
set selectedFields {}; set i 0
foreach severity $severities {lappend selectedFields $i string $severity; incr i}
set unknownFields {}; set unknownSelected 0
dict for {severity count} $unknownTimeTotals {
    lappend unknownFields $severity number $count
    incr unknownSelected $count
}
set ordered {}
dict for {key group} $groups {lappend ordered [list [dict get $group count] $group]}
set entries {}
set index 0
foreach pair [lsort -integer -decreasing -index 0 $ordered] {
    set group [lindex $pair 1]
    set fields {}
    foreach name {severity pattern example requestIdentifier} {lappend fields $name string [dict get $group $name]}
    foreach name {count firstAt lastAt} {lappend fields $name number [dict get $group $name]}
    lappend fields exampleTruncated boolean [dict get $group exampleTruncated]
    lappend entries $index object $fields
    incr index
}
# Observed entry times describe only bytes scanned so far, not rotation or
# proof of complete coverage. File mtime is deliberately not used as a date.
set bounds [list source string observed-timestamped-entries scope string scanned-file  timestampedRecords number $timestampedRecords]
foreach name {earliestAt latestAt firstEntryAt lastEntryAt firstEntryOffset lastEntryOffset} {
    set value [set $name]
    lappend bounds $name [expr {$value eq "" ? "null" : "number"}] $value
}
set logTimezone :localtime
if {[info exists ::env(TZ)] && $::env(TZ) ne ""} {set logTimezone $::env(TZ)}
# System-log rotations may be scheduled by application code or external
# tools. nslog's logrollhour describes access logs, not this source.
set rotation [list scheduleKnown boolean false schedule null {} lastVerifiedAt null {}  timezone string $logTimezone  onSignal boolean [ns_config -bool ns/parameters logrollonsignal  [ns_config -bool ns/parameters logroll true]]  filenameFormat string [ns_config ns/parameters logrollfmt {}]  configurationScope string process-system-log  limitations string {Signal handling and filename format are configuration, not proof of rotation. A daily schedule and last successful rotation time are not exposed by this interface; application or external rotation is possible.}]
set result [list {} object [list server string [ns_info server] scope string process  from number $from to number $to timezone string [dict get $options timezone]  timestampTimezone string [clock format [clock seconds] -format %Z]  selectedSeverities array $selectedFields severityTotals object $severityFields matchedRecords number $matched ungroupedRecords number $ungrouped groups array $entries  grouping string {Redacted first line; numeric tokens and hex addresses normalized. Groups are bounded by first encounter, then sorted by count.}  coverage object [list logBounds object $bounds rotation object $rotation sourceBytes number $before(size) examinedFromOffset number $start examinedToOffset number $examined  sourceFullyExamined boolean [expr {$stable && $start==0 && $examined==$before(size)}]  sourceChanged boolean [expr {!$stable}] historyUnreadBytes number $start  unreadBytes number [expr {max(0,$before(size)-$examined)}]  unknownTimeErrors number $unknownTime unknownTimeRecords number $unknownSelected  unknownTimeSeverityTotals object $unknownFields unrecognizedRecords number $unrecognized  unrecognizedExamples array $exampleEntries  mutexTraceRecords number $mutexTraces mutexTraceGroups array $mutexEntries  mutexTraceUngroupedRecords number $mutexUngrouped shortLogRecords number $shortEntries  untimestampedRecords number $untimestamped untimestampedExamples array $untimestampedEntries  postgresRecords number $postgresRecords postgresExamples array $postgresEntries  diagnosticScope string scanned-file  clippedExamples number $clipped pendingFinalRecord boolean $pending  rotationsExamined boolean false windowComplete boolean false  limitations string {Only the configured current system log is examined. Rotated files and time before this file are not certified. Counts include observed final records, whose continuations may still grow. Expected ns:sched unlock/hold diagnostics are omitted entirely. Other mutex traces are grouped by mutex name, operation and wait/hold metric over every scanned trace (up to 128 groups; excess records are counted in mutexTraceUngroupedRecords). Durations are individual observations, not additive wall time or proof of contention. Negative durations indicate timing diagnostics, not valid waits. Mutex traces and short system-log entries have no timestamps; diagnostic counters and examples cover the scanned file, not necessarily the requested time window. PostgreSQL DETAIL, HINT and CONTEXT fields are grouped with their diagnostic. postgresExamples provides explicitly inferred neighboring timestamp bounds, which may be missing or out of order under concurrent logging; these are contextual estimates, not guaranteed event times or request attribution. No timestamps are inherited from adjacent entries. Untimestamped selected severities contribute to unknownTimeRecords and unknownTimeSeverityTotals, not window severityTotals; unknownTimeErrors retains only Error/Fatal/Bug.}]]]
if {$state ne ""} {lappend result $state}
return $result

XQL Not present:

Generic, PostgreSQL, Oracle