mirror of
https://github.com/permissionlesstech/bitchat.git
synced 2026-07-25 18:45:20 +00:00
Stop paying for filtered log messages; sample per-event hot-path logs
SecureLogger's public wrappers evaluated their message autoclosure before the level check inside log(), so every filtered debug message across the codebase still paid for string interpolation - hundreds of call sites on the per-packet/per-event hot paths. The wrappers now guard the level first, and debug() compiles out of release builds entirely. Regression tests verify filtered messages are never constructed. The two heaviest per-event debug logs (NostrRelayManager inbound events, ChatNostrCoordinator geo events) are now sampled every 100th with a running count, so debug-enabled dev builds stop emitting hundreds of lines per minute in busy geohashes. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
@@ -152,6 +152,7 @@ final class NostrRelayManager: ObservableObject {
|
|||||||
private var recentInboundEventKeyOrder: [InboundEventKey] = []
|
private var recentInboundEventKeyOrder: [InboundEventKey] = []
|
||||||
private var duplicateInboundEventDropCount = 0
|
private var duplicateInboundEventDropCount = 0
|
||||||
private var duplicateInboundEventDropCountBySubscription: [String: Int] = [:]
|
private var duplicateInboundEventDropCountBySubscription: [String: Int] = [:]
|
||||||
|
private var inboundEventLogCount = 0
|
||||||
// Coalesce duplicate subscribe requests for the same id within a short window.
|
// Coalesce duplicate subscribe requests for the same id within a short window.
|
||||||
private let subscribeCoalesceInterval: TimeInterval = 1.0
|
private let subscribeCoalesceInterval: TimeInterval = 1.0
|
||||||
private var subscribeCoalesce: [String: Date] = [:]
|
private var subscribeCoalesce: [String: Date] = [:]
|
||||||
@@ -834,7 +835,11 @@ final class NostrRelayManager: ObservableObject {
|
|||||||
return
|
return
|
||||||
}
|
}
|
||||||
if event.kind != 1059 {
|
if event.kind != 1059 {
|
||||||
SecureLogger.debug("📥 Event kind=\(event.kind) id=\(event.id.prefix(16))… relay=\(relayUrl)", category: .session)
|
// Per-event logging floods dev builds in busy geohashes; sample it.
|
||||||
|
inboundEventLogCount += 1
|
||||||
|
if inboundEventLogCount == 1 || inboundEventLogCount.isMultiple(of: TransportConfig.nostrInboundEventLogInterval) {
|
||||||
|
SecureLogger.debug("📥 Event #\(inboundEventLogCount) kind=\(event.kind) id=\(event.id.prefix(16))… relay=\(relayUrl)", category: .session)
|
||||||
|
}
|
||||||
}
|
}
|
||||||
if let handler = self.messageHandlers[subId] {
|
if let handler = self.messageHandlers[subId] {
|
||||||
handler(event)
|
handler(event)
|
||||||
|
|||||||
@@ -47,6 +47,8 @@ enum TransportConfig {
|
|||||||
static let nostrInboundEventDedupCap: Int = 4096
|
static let nostrInboundEventDedupCap: Int = 4096
|
||||||
static let nostrInboundEventDedupTrimTarget: Int = 3072
|
static let nostrInboundEventDedupTrimTarget: Int = 3072
|
||||||
static let nostrDuplicateEventLogInterval: Int = 50
|
static let nostrDuplicateEventLogInterval: Int = 50
|
||||||
|
// Sample interval for per-event debug logs on the inbound hot path.
|
||||||
|
static let nostrInboundEventLogInterval: Int = 100
|
||||||
|
|
||||||
// UI thresholds
|
// UI thresholds
|
||||||
static let uiLateInsertThreshold: TimeInterval = 15.0
|
static let uiLateInsertThreshold: TimeInterval = 15.0
|
||||||
|
|||||||
@@ -191,6 +191,7 @@ final class ChatNostrCoordinator {
|
|||||||
private weak var context: (any ChatNostrContext)?
|
private weak var context: (any ChatNostrContext)?
|
||||||
private var recentGeoSamplingEventIDs = Set<String>()
|
private var recentGeoSamplingEventIDs = Set<String>()
|
||||||
private var recentGeoSamplingEventIDOrder: [String] = []
|
private var recentGeoSamplingEventIDOrder: [String] = []
|
||||||
|
private var geoEventLogCount = 0
|
||||||
|
|
||||||
init(context: any ChatNostrContext) {
|
init(context: any ChatNostrContext) {
|
||||||
self.context = context
|
self.context = context
|
||||||
@@ -450,8 +451,11 @@ final class ChatNostrCoordinator {
|
|||||||
if context.hasProcessedNostrEvent(event.id) { return }
|
if context.hasProcessedNostrEvent(event.id) { return }
|
||||||
context.recordProcessedNostrEvent(event.id)
|
context.recordProcessedNostrEvent(event.id)
|
||||||
|
|
||||||
let tagSummary = event.tags.map { "[" + $0.joined(separator: ",") + "]" }.joined(separator: ",")
|
// Sampled: fires for every geo event and floods dev logs in busy geohashes.
|
||||||
SecureLogger.debug("GeoTeleport: recv pub=\(event.pubkey.prefix(8))… tags=\(tagSummary)", category: .session)
|
geoEventLogCount += 1
|
||||||
|
if geoEventLogCount == 1 || geoEventLogCount.isMultiple(of: TransportConfig.nostrInboundEventLogInterval) {
|
||||||
|
SecureLogger.debug("GeoTeleport: recv #\(geoEventLogCount) pub=\(event.pubkey.prefix(8))… tags=\(event.tags.map { "[" + $0.joined(separator: ",") + "]" }.joined(separator: ","))", category: .session)
|
||||||
|
}
|
||||||
|
|
||||||
if context.isNostrBlocked(pubkeyHexLowercased: event.pubkey) {
|
if context.isNostrBlocked(pubkeyHexLowercased: event.pubkey) {
|
||||||
return
|
return
|
||||||
|
|||||||
@@ -101,7 +101,8 @@ public final class SecureLogger {
|
|||||||
// MARK: - Global Threshold
|
// MARK: - Global Threshold
|
||||||
|
|
||||||
/// Minimum level that will be logged. Defaults to .info. Override via env BITCHAT_LOG_LEVEL.
|
/// Minimum level that will be logged. Defaults to .info. Override via env BITCHAT_LOG_LEVEL.
|
||||||
private static let minimumLevel: LogLevel = {
|
/// Internal-settable so tests can verify level filtering; app code should not mutate it.
|
||||||
|
internal static var minimumLevel: LogLevel = {
|
||||||
let env = ProcessInfo.processInfo.environment["BITCHAT_LOG_LEVEL"]?.lowercased()
|
let env = ProcessInfo.processInfo.environment["BITCHAT_LOG_LEVEL"]?.lowercased()
|
||||||
switch env {
|
switch env {
|
||||||
case "debug": return .debug
|
case "debug": return .debug
|
||||||
@@ -121,23 +122,33 @@ public final class SecureLogger {
|
|||||||
|
|
||||||
public extension SecureLogger {
|
public extension SecureLogger {
|
||||||
|
|
||||||
|
// Each wrapper checks the level BEFORE evaluating the autoclosure so
|
||||||
|
// filtered messages never pay for string interpolation — this matters on
|
||||||
|
// hot paths that log per packet/event. Debug compiles out of release
|
||||||
|
// builds entirely (the core log() drops .debug there anyway).
|
||||||
static func debug(_ message: @autoclosure () -> String, category: OSLog = .noise,
|
static func debug(_ message: @autoclosure () -> String, category: OSLog = .noise,
|
||||||
file: String = #file, line: Int = #line, function: String = #function) {
|
file: String = #file, line: Int = #line, function: String = #function) {
|
||||||
|
#if DEBUG
|
||||||
|
guard shouldLog(.debug) else { return }
|
||||||
log(message(), category: category, level: .debug, file: file, line: line, function: function)
|
log(message(), category: category, level: .debug, file: file, line: line, function: function)
|
||||||
|
#endif
|
||||||
}
|
}
|
||||||
|
|
||||||
static func info(_ message: @autoclosure () -> String, category: OSLog = .noise,
|
static func info(_ message: @autoclosure () -> String, category: OSLog = .noise,
|
||||||
file: String = #file, line: Int = #line, function: String = #function) {
|
file: String = #file, line: Int = #line, function: String = #function) {
|
||||||
|
guard shouldLog(.info) else { return }
|
||||||
log(message(), category: category, level: .info, file: file, line: line, function: function)
|
log(message(), category: category, level: .info, file: file, line: line, function: function)
|
||||||
}
|
}
|
||||||
|
|
||||||
static func warning(_ message: @autoclosure () -> String, category: OSLog = .noise,
|
static func warning(_ message: @autoclosure () -> String, category: OSLog = .noise,
|
||||||
file: String = #file, line: Int = #line, function: String = #function) {
|
file: String = #file, line: Int = #line, function: String = #function) {
|
||||||
|
guard shouldLog(.warning) else { return }
|
||||||
log(message(), category: category, level: .warning, file: file, line: line, function: function)
|
log(message(), category: category, level: .warning, file: file, line: line, function: function)
|
||||||
}
|
}
|
||||||
|
|
||||||
static func error(_ message: @autoclosure () -> String, category: OSLog = .noise,
|
static func error(_ message: @autoclosure () -> String, category: OSLog = .noise,
|
||||||
file: String = #file, line: Int = #line, function: String = #function) {
|
file: String = #file, line: Int = #line, function: String = #function) {
|
||||||
|
guard shouldLog(.error) else { return }
|
||||||
log(message(), category: category, level: .error, file: file, line: line, function: function)
|
log(message(), category: category, level: .error, file: file, line: line, function: function)
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -0,0 +1,54 @@
|
|||||||
|
import XCTest
|
||||||
|
@testable import BitLogger
|
||||||
|
|
||||||
|
/// The public logging wrappers must not evaluate their message autoclosure
|
||||||
|
/// when the level is filtered out — hot paths log per packet/event, and
|
||||||
|
/// building a discarded interpolated string on each call is real overhead.
|
||||||
|
final class LogLevelFilteringTests: XCTestCase {
|
||||||
|
private final class EvaluationCounter {
|
||||||
|
var count = 0
|
||||||
|
func message() -> String {
|
||||||
|
count += 1
|
||||||
|
return "expensive interpolation"
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
private var originalLevel: SecureLogger.LogLevel!
|
||||||
|
|
||||||
|
override func setUp() {
|
||||||
|
super.setUp()
|
||||||
|
originalLevel = SecureLogger.minimumLevel
|
||||||
|
}
|
||||||
|
|
||||||
|
override func tearDown() {
|
||||||
|
SecureLogger.minimumLevel = originalLevel
|
||||||
|
super.tearDown()
|
||||||
|
}
|
||||||
|
|
||||||
|
func testFilteredDebugMessageIsNeverEvaluated() {
|
||||||
|
SecureLogger.minimumLevel = .info
|
||||||
|
let counter = EvaluationCounter()
|
||||||
|
|
||||||
|
SecureLogger.debug(counter.message())
|
||||||
|
|
||||||
|
XCTAssertEqual(counter.count, 0, "Filtered debug message should not be constructed")
|
||||||
|
}
|
||||||
|
|
||||||
|
func testFilteredInfoMessageIsNeverEvaluated() {
|
||||||
|
SecureLogger.minimumLevel = .error
|
||||||
|
let counter = EvaluationCounter()
|
||||||
|
|
||||||
|
SecureLogger.info(counter.message())
|
||||||
|
|
||||||
|
XCTAssertEqual(counter.count, 0, "Filtered info message should not be constructed")
|
||||||
|
}
|
||||||
|
|
||||||
|
func testEnabledLevelStillEvaluatesMessage() {
|
||||||
|
SecureLogger.minimumLevel = .debug
|
||||||
|
let counter = EvaluationCounter()
|
||||||
|
|
||||||
|
SecureLogger.warning(counter.message())
|
||||||
|
|
||||||
|
XCTAssertEqual(counter.count, 1, "Enabled levels must still log")
|
||||||
|
}
|
||||||
|
}
|
||||||
Reference in New Issue
Block a user