diff --git a/bitchat/Nostr/NostrRelayManager.swift b/bitchat/Nostr/NostrRelayManager.swift index 2366c68c..2f261548 100644 --- a/bitchat/Nostr/NostrRelayManager.swift +++ b/bitchat/Nostr/NostrRelayManager.swift @@ -152,6 +152,7 @@ final class NostrRelayManager: ObservableObject { private var recentInboundEventKeyOrder: [InboundEventKey] = [] private var duplicateInboundEventDropCount = 0 private var duplicateInboundEventDropCountBySubscription: [String: Int] = [:] + private var inboundEventLogCount = 0 // Coalesce duplicate subscribe requests for the same id within a short window. private let subscribeCoalesceInterval: TimeInterval = 1.0 private var subscribeCoalesce: [String: Date] = [:] @@ -834,7 +835,11 @@ final class NostrRelayManager: ObservableObject { return } 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] { handler(event) diff --git a/bitchat/Services/TransportConfig.swift b/bitchat/Services/TransportConfig.swift index 846689d1..6ecf5d1d 100644 --- a/bitchat/Services/TransportConfig.swift +++ b/bitchat/Services/TransportConfig.swift @@ -47,6 +47,8 @@ enum TransportConfig { static let nostrInboundEventDedupCap: Int = 4096 static let nostrInboundEventDedupTrimTarget: Int = 3072 static let nostrDuplicateEventLogInterval: Int = 50 + // Sample interval for per-event debug logs on the inbound hot path. + static let nostrInboundEventLogInterval: Int = 100 // UI thresholds static let uiLateInsertThreshold: TimeInterval = 15.0 diff --git a/bitchat/ViewModels/ChatNostrCoordinator.swift b/bitchat/ViewModels/ChatNostrCoordinator.swift index 54ef82cf..2c27223e 100644 --- a/bitchat/ViewModels/ChatNostrCoordinator.swift +++ b/bitchat/ViewModels/ChatNostrCoordinator.swift @@ -191,6 +191,7 @@ final class ChatNostrCoordinator { private weak var context: (any ChatNostrContext)? private var recentGeoSamplingEventIDs = Set() private var recentGeoSamplingEventIDOrder: [String] = [] + private var geoEventLogCount = 0 init(context: any ChatNostrContext) { self.context = context @@ -450,8 +451,11 @@ final class ChatNostrCoordinator { if context.hasProcessedNostrEvent(event.id) { return } context.recordProcessedNostrEvent(event.id) - let tagSummary = event.tags.map { "[" + $0.joined(separator: ",") + "]" }.joined(separator: ",") - SecureLogger.debug("GeoTeleport: recv pub=\(event.pubkey.prefix(8))… tags=\(tagSummary)", category: .session) + // Sampled: fires for every geo event and floods dev logs in busy geohashes. + 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) { return diff --git a/localPackages/BitLogger/Sources/SecureLogger.swift b/localPackages/BitLogger/Sources/SecureLogger.swift index b6645ea1..2599dfdf 100644 --- a/localPackages/BitLogger/Sources/SecureLogger.swift +++ b/localPackages/BitLogger/Sources/SecureLogger.swift @@ -101,7 +101,8 @@ public final class SecureLogger { // MARK: - Global Threshold /// 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() switch env { case "debug": return .debug @@ -121,23 +122,33 @@ public final class 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, 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) + #endif } - + static func info(_ message: @autoclosure () -> String, category: OSLog = .noise, 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) } - + static func warning(_ message: @autoclosure () -> String, category: OSLog = .noise, 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) } - + static func error(_ message: @autoclosure () -> String, category: OSLog = .noise, 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) } diff --git a/localPackages/BitLogger/Tests/LogLevelFilteringTests.swift b/localPackages/BitLogger/Tests/LogLevelFilteringTests.swift new file mode 100644 index 00000000..db04759f --- /dev/null +++ b/localPackages/BitLogger/Tests/LogLevelFilteringTests.swift @@ -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") + } +}