Fixed a few minor issues noticed in the logs

• Fixed an issue where SOGS pollers could be started multiple times
• Avoid checking if blinded conversations exist in the config (will always return false)
• Updated some logs to provide more timing information
pull/976/head
Morgan Pretty 1 month ago
parent 1bc294114b
commit 3b5eaa6bbb

@ -808,6 +808,7 @@
FDB7400D28EBEC240094D718 /* DateHeaderCell.swift in Sources */ = {isa = PBXBuildFile; fileRef = FDB7400C28EBEC240094D718 /* DateHeaderCell.swift */; };
FDBB25E32988B13800F1508E /* _004_AddJobPriority.swift in Sources */ = {isa = PBXBuildFile; fileRef = FDBB25E22988B13800F1508E /* _004_AddJobPriority.swift */; };
FDBB25E72988BBBE00F1508E /* UIContextualAction+Theming.swift in Sources */ = {isa = PBXBuildFile; fileRef = FDBB25E62988BBBD00F1508E /* UIContextualAction+Theming.swift */; };
FDC0F0042BFECE12002CBFB9 /* TimeUnit.swift in Sources */ = {isa = PBXBuildFile; fileRef = FDC0F0032BFECE12002CBFB9 /* TimeUnit.swift */; };
FDC13D472A16E4CA007267C7 /* SubscribeRequest.swift in Sources */ = {isa = PBXBuildFile; fileRef = FDC13D462A16E4CA007267C7 /* SubscribeRequest.swift */; };
FDC13D492A16EC20007267C7 /* Service.swift in Sources */ = {isa = PBXBuildFile; fileRef = FDC13D482A16EC20007267C7 /* Service.swift */; };
FDC13D4B2A16ECBA007267C7 /* SubscribeResponse.swift in Sources */ = {isa = PBXBuildFile; fileRef = FDC13D4A2A16ECBA007267C7 /* SubscribeResponse.swift */; };
@ -1994,6 +1995,7 @@
FDB7400C28EBEC240094D718 /* DateHeaderCell.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = DateHeaderCell.swift; sourceTree = "<group>"; };
FDBB25E22988B13800F1508E /* _004_AddJobPriority.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = _004_AddJobPriority.swift; sourceTree = "<group>"; };
FDBB25E62988BBBD00F1508E /* UIContextualAction+Theming.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = "UIContextualAction+Theming.swift"; sourceTree = "<group>"; };
FDC0F0032BFECE12002CBFB9 /* TimeUnit.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = TimeUnit.swift; sourceTree = "<group>"; };
FDC13D462A16E4CA007267C7 /* SubscribeRequest.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SubscribeRequest.swift; sourceTree = "<group>"; };
FDC13D482A16EC20007267C7 /* Service.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = Service.swift; sourceTree = "<group>"; };
FDC13D4A2A16ECBA007267C7 /* SubscribeResponse.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = SubscribeResponse.swift; sourceTree = "<group>"; };
@ -3688,6 +3690,7 @@
FD09797127FAA2F500936362 /* Optional+Utilities.swift */,
FD09797C27FBDB2000936362 /* Notification+Utilities.swift */,
FDF222082818D2B0000A4995 /* NSAttributedString+Utilities.swift */,
FDC0F0032BFECE12002CBFB9 /* TimeUnit.swift */,
FD8ECF912938552800C0D1BB /* Threading.swift */,
FD8ECF93293856AF00C0D1BB /* Randomness.swift */,
FD1936402ACA7BD8004BCF0F /* Result+Utilities.swift */,
@ -5974,6 +5977,7 @@
FDF8487B29405906007DCAE5 /* HTTPHeader.swift in Sources */,
FD9004122818ABDC00ABAAF6 /* Job.swift in Sources */,
FD09797927FAB7E800936362 /* ImageFormat.swift in Sources */,
FDC0F0042BFECE12002CBFB9 /* TimeUnit.swift in Sources */,
FD7115FE28C8202D00B47552 /* ReplaySubject.swift in Sources */,
C32C5DC9256DD935003C73A2 /* ProxiedContentDownloader.swift in Sources */,
FD7F745F2BAAA3B4006DDFD8 /* TypeConversion+Utilities.swift in Sources */,
@ -7977,7 +7981,7 @@
CLANG_WARN__ARC_BRIDGE_CAST_NONARC = YES;
CLANG_WARN__DUPLICATE_METHOD_MATCH = YES;
CODE_SIGN_IDENTITY = "iPhone Developer";
CURRENT_PROJECT_VERSION = 445;
CURRENT_PROJECT_VERSION = 446;
ENABLE_BITCODE = NO;
ENABLE_STRICT_OBJC_MSGSEND = YES;
ENABLE_TESTABILITY = YES;
@ -8055,7 +8059,7 @@
CLANG_WARN__ARC_BRIDGE_CAST_NONARC = YES;
CLANG_WARN__DUPLICATE_METHOD_MATCH = YES;
CODE_SIGN_IDENTITY = "iPhone Distribution";
CURRENT_PROJECT_VERSION = 445;
CURRENT_PROJECT_VERSION = 446;
ENABLE_BITCODE = NO;
ENABLE_STRICT_OBJC_MSGSEND = YES;
GCC_NO_COMMON_BLOCKS = YES;

@ -405,8 +405,8 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
// Add a log to track the proper startup time of the app so we know whether we need to
// improve it in the future from user logs
let endTime: CFTimeInterval = CACurrentMediaTime()
Log.info("\(lifecycleMethod.timingName) completed in \((self?.startTime).map { ceil((endTime - $0) * 1000) } ?? -1)ms")
let startupDuration: CFTimeInterval = ((self?.startTime).map { CACurrentMediaTime() - $0 } ?? -1)
Log.info("\(lifecycleMethod.timingName) completed in \(.seconds(startupDuration), unit: .ms).")
}
// May as well run these on the background thread

@ -384,6 +384,15 @@ public extension LibSession {
threadVariant: SessionThread.Variant,
visibleOnly: Bool
) -> Bool {
// Currently blinded conversations cannot be contained in the config, so there is no point checking (it'll always be
// false)
guard
threadVariant == .community || (
SessionId(from: threadId)?.prefix != .blinded15 &&
SessionId(from: threadId)?.prefix != .blinded25
)
else { return false }
let userPublicKey: String = getUserHexEncodedPublicKey(db)
let configVariant: ConfigDump.Variant = {
switch threadVariant {

@ -291,6 +291,26 @@ public final class OpenGroupManager {
on: targetServer,
using: dependencies
) {
// Dispatch async to the workQueue to prevent holding up the thread
OpenGroupAPI.workQueue.async(using: dependencies) {
// (Re)start the poller if needed (want to force it to poll immediately in the next
// run loop to avoid a big delay before the next poll)
let poller: OpenGroupAPI.Poller = dependencies.caches.mutate(cache: .openGroupManager) {
// Don't create a new poller instance if one already exists so we don't
// double up on pollers
guard let poller: OpenGroupAPI.Poller = $0.pollers[server.lowercased()] else {
let poller: OpenGroupAPI.Poller = OpenGroupAPI.Poller(for: server.lowercased())
$0.pollers[server.lowercased()] = poller
return poller
}
return poller
}
poller.stop()
poller.startIfNeeded(using: dependencies)
}
resolver(Result.success(()))
}
}
@ -498,17 +518,6 @@ public final class OpenGroupManager {
// Dispatch async to the workQueue to prevent holding up the DBWrite thread from the
// above transaction
OpenGroupAPI.workQueue.async(using: dependencies) {
// (Re)start the poller if needed (want to force it to poll immediately in the next
// run loop to avoid a big delay before the next poll)
dependencies.caches.mutate(cache: .openGroupManager) {
$0.pollers[server.lowercased()]?.stop()
$0.pollers[server.lowercased()] = OpenGroupAPI.Poller(for: server.lowercased())
}
OpenGroupAPI.workQueue.async(using: dependencies) {
dependencies.caches[.openGroupManager].pollers[server.lowercased()]?
.startIfNeeded(using: dependencies)
}
/// Start downloading the room image (if we don't have one or it's been updated)
if
let imageId: String = (pollInfo.details?.imageId ?? openGroup.imageId),

@ -11,7 +11,7 @@ extension OpenGroupAPI {
typealias PollResponse = (info: ResponseInfoType, data: [OpenGroupAPI.Endpoint: Decodable])
private let server: String
private var timer: Timer? = nil
private var recursiveLoopId: UUID = UUID()
private var hasStarted: Bool = false
private var isPolling: Bool = false
@ -39,12 +39,13 @@ extension OpenGroupAPI {
guard !hasStarted else { return }
hasStarted = true
recursiveLoopId = UUID()
pollRecursively(using: dependencies)
}
@objc public func stop() {
timer?.invalidate()
hasStarted = false
recursiveLoopId = UUID()
}
// MARK: - Polling
@ -53,6 +54,7 @@ extension OpenGroupAPI {
guard hasStarted else { return }
let server: String = self.server
let originalRecursiveLoopId: UUID = self.recursiveLoopId
let lastPollStart: TimeInterval = dependencies.dateNow.timeIntervalSince1970
poll(using: dependencies)
@ -82,34 +84,32 @@ extension OpenGroupAPI {
// Schedule the next poll
guard remainingInterval > 0 else {
return Threading.communityPollerQueue.async(using: dependencies) {
// If we started a new recursive loop then we don't want to double up so just let this
// one stop looping
guard originalRecursiveLoopId == self?.recursiveLoopId else { return }
self?.pollRecursively(using: dependencies)
}
}
Threading.communityPollerQueue.asyncAfter(deadline: .now() + .milliseconds(Int(remainingInterval * 1000)), qos: .default, using: dependencies) {
// If we started a new recursive loop then we don't want to double up so just let this
// one stop looping
guard originalRecursiveLoopId == self?.recursiveLoopId else { return }
self?.pollRecursively(using: dependencies)
}
}
)
}
public func poll(
using dependencies: Dependencies = Dependencies()
) -> AnyPublisher<Void, Error> {
return poll(
calledFromBackgroundPoller: false,
isPostCapabilitiesRetry: false,
using: dependencies
)
}
public func poll(
calledFromBackgroundPoller: Bool,
calledFromBackgroundPoller: Bool = false,
isBackgroundPollerValid: @escaping (() -> Bool) = { true },
isPostCapabilitiesRetry: Bool,
isPostCapabilitiesRetry: Bool = false,
using dependencies: Dependencies = Dependencies()
) -> AnyPublisher<Void, Error> {
guard !self.isPolling else {
guard !self.isPolling && self.hasStarted else {
return Just(())
.setFailureType(to: Error.self)
.eraseToAnyPublisher()
@ -117,6 +117,7 @@ extension OpenGroupAPI {
self.isPolling = true
let server: String = self.server
let pollStartTime: TimeInterval = dependencies.dateNow.timeIntervalSince1970
let hasPerformedInitialPoll: Bool = (dependencies.caches[.openGroupManager].hasPerformedInitialPoll[server] == true)
let timeSinceLastPoll: TimeInterval = (
dependencies.caches[.openGroupManager].timeSinceLastPoll[server] ??
@ -156,6 +157,7 @@ extension OpenGroupAPI {
// If this was a background poll and the background poll is no longer valid
// then just stop
self?.isPolling = false
self?.hasStarted = false
return
}
@ -167,25 +169,27 @@ extension OpenGroupAPI {
using: dependencies
)
dependencies.caches.mutate(cache: .openGroupManager) { cache in
cache.hasPerformedInitialPoll[server] = true
cache.timeSinceLastPoll[server] = dependencies.dateNow.timeIntervalSince1970
dependencies.standardUserDefaults[.lastOpen] = dependencies.dateNow
}
SNLog("Open group polling finished for \(server).")
let pollEndTime: TimeInterval = dependencies.dateNow.timeIntervalSince1970
SNLog("Open group polling finished for \(server) in \(.seconds(pollEndTime - pollStartTime), unit: .s).")
}
)
.map { _ in () }
.catch { [weak self] error -> AnyPublisher<Void, Error> in
guard
let strongSelf = self,
strongSelf.hasStarted,
(!calledFromBackgroundPoller || isBackgroundPollerValid())
else {
// If this was a background poll and the background poll is no longer valid
// then just stop
self?.isPolling = false
self?.hasStarted = false
return Just(())
.setFailureType(to: Error.self)
@ -275,7 +279,8 @@ extension OpenGroupAPI {
}
}
SNLog("Open group polling to \(server) failed due to error: \(error). Setting failure count to \(pollFailureCount + 1).")
let pollEndTime: TimeInterval = dependencies.dateNow.timeIntervalSince1970
SNLog("Open group polling to \(server) failed in \(.seconds(pollEndTime - pollStartTime), unit: .s) due to error: \(error). Setting failure count to \(pollFailureCount + 1).")
// Add a note to the logs that this happened
if !prunedIds.isEmpty {
@ -301,7 +306,7 @@ extension OpenGroupAPI {
isBackgroundPollerValid: @escaping (() -> Bool) = { true },
isPostCapabilitiesRetry: Bool,
error: Error,
using dependencies: Dependencies = Dependencies()
using dependencies: Dependencies
) -> AnyPublisher<Bool, Error> {
/// We want to custom handle a '400' error code due to not having blinded auth as it likely means that we join the
/// OpenGroup before blinding was enabled and need to update it's capabilities
@ -330,7 +335,7 @@ extension OpenGroupAPI {
}
.flatMap { $0.send(using: dependencies) }
.flatMap { [weak self] _, responseBody -> AnyPublisher<Void, Error> in
guard let strongSelf = self, isBackgroundPollerValid() else {
guard let strongSelf = self, strongSelf.hasStarted, isBackgroundPollerValid() else {
return Just(())
.setFailureType(to: Error.self)
.eraseToAnyPublisher()
@ -360,7 +365,7 @@ extension OpenGroupAPI {
}
.map { _ in true }
.catch { error -> AnyPublisher<Bool, Error> in
SNLog("Open group updating capabilities failed due to error: \(error).")
SNLog("Open group updating capabilities for \(server) failed due to error: \(error).")
return Just(true)
.setFailureType(to: Error.self)
.eraseToAnyPublisher()

@ -98,7 +98,6 @@ public class Poller {
let namespaces: [SnodeAPI.Namespace] = self.namespaces
let pollerQueue: DispatchQueue = self.pollerQueue
let lastPollStart: TimeInterval = dependencies.dateNow.timeIntervalSince1970
let lastPollInterval: TimeInterval = nextPollDelay(for: swarmPublicKey, using: dependencies)
// Store the publisher intp the cancellables dictionary
cancellables.mutate { [weak self] cancellables in
@ -122,16 +121,15 @@ public class Poller {
case .finished: break
}
// Calculate the remaining poll delay
// Calculate the remaining poll delay and schedule the next poll
let currentTime: TimeInterval = dependencies.dateNow.timeIntervalSince1970
let nextPollInterval: TimeInterval = (
self?.nextPollDelay(for: swarmPublicKey, using: dependencies) ??
lastPollInterval
)
let remainingInterval: TimeInterval = max(0, nextPollInterval - (currentTime - lastPollStart))
// Schedule the next poll
guard remainingInterval > 0 else {
guard
self != nil,
let remainingInterval: TimeInterval = (self?.nextPollDelay(for: swarmPublicKey, using: dependencies))
.map({ nextPollInterval in max(0, nextPollInterval - (currentTime - lastPollStart)) }),
remainingInterval > 0
else {
return pollerQueue.async(using: dependencies) {
self?.pollRecursively(for: swarmPublicKey, drainBehaviour: drainBehaviour, using: dependencies)
}
@ -172,6 +170,7 @@ public class Poller {
let pollerName: String = pollerName(for: swarmPublicKey)
let pollerQueue: DispatchQueue = self.pollerQueue
let configHashes: [String] = LibSession.configHashes(for: swarmPublicKey)
let pollStartTime: TimeInterval = dependencies.dateNow.timeIntervalSince1970
// Fetch the messages
return LibSession.getSwarm(swarmPublicKey: swarmPublicKey)
@ -202,7 +201,10 @@ public class Poller {
// No need to do anything if there are no messages
guard rawMessageCount > 0 else {
if !calledFromBackgroundPoller { SNLog("Received no new messages in \(pollerName)") }
if !calledFromBackgroundPoller {
let pollEndTime: TimeInterval = dependencies.dateNow.timeIntervalSince1970
SNLog("Received no new messages in \(pollerName) after \(.seconds(pollEndTime - pollStartTime), unit: .s).")
}
return Just([])
.setFailureType(to: Error.self)
@ -392,11 +394,12 @@ public class Poller {
}
// Set the output for logging
pollerLogOutput = "Received \(messageCount) new message\(messageCount == 1 ? "" : "s") in \(pollerName) (duplicates: \(rawMessageCount - messageCount))" // stringlint:disable
let pollEndTime: TimeInterval = dependencies.dateNow.timeIntervalSince1970
pollerLogOutput = "Received \(messageCount) new message\(messageCount == 1 ? "" : "s") in \(pollerName) after \(.seconds(pollEndTime - pollStartTime), unit: .s) (duplicates: \(rawMessageCount - messageCount))" // stringlint:disable
// Clean up message hashes and add some logs about the poll results
if sortedMessages.isEmpty && !hadValidHashUpdate {
pollerLogOutput = "Received \(rawMessageCount) new message\(rawMessageCount == 1 ? "" : "s") in \(pollerName), all duplicates - marking the hash we polled with as invalid" // stringlint:disable
pollerLogOutput = "Received \(rawMessageCount) new message\(rawMessageCount == 1 ? "" : "s") in \(pollerName) after \(.seconds(pollEndTime - pollStartTime), unit: .s), all duplicates - marking the hash we polled with as invalid" // stringlint:disable
// Update the cached validity of the messages
try SnodeReceivedMessageInfo.handlePotentialDeletedOrInvalidHash(

@ -37,8 +37,8 @@ public enum Log {
public static func enterForeground() {
guard logger.wrappedValue != nil else { return }
OWSLogger.info("")
OWSLogger.info("")
Log.empty()
Log.empty()
}
public static func logFilePath() -> String? {
@ -55,6 +55,24 @@ public enum Log {
// MARK: - Log Functions
fileprivate static func empty() {
let emptyArguments: [CVarArg] = []
withVaList(emptyArguments) { ptr in
DDLog.log(
asynchronous: true,
level: .info,
flag: .info,
context: 0,
file: "",
function: "",
line: 0,
tag: nil,
format: "",
arguments: ptr)
}
}
public static func trace(
_ message: String,
withPrefixes: Bool = true,
@ -244,8 +262,8 @@ public class Logger {
}
// After creating a new logger we want to log two empty lines to make it easier to read
OWSLogger.info("")
OWSLogger.info("")
Log.empty()
Log.empty()
// Add any logs that were pending during the startup process
pendingLogs.forEach { level, message, withPrefixes, silenceForTests in

@ -77,7 +77,11 @@ public extension String {
// MARK: - Formatting
extension String.StringInterpolation {
public extension String.StringInterpolation {
mutating func appendInterpolation(_ value: TimeUnit, unit: TimeUnit.Unit, resolution: Int = 2) {
appendLiteral("\(TimeUnit(value, unit: unit, resolution: resolution))")
}
mutating func appendInterpolation(_ value: Int, format: String) {
let result: String = String(format: "%\(format)d", value)
appendLiteral(result)

@ -0,0 +1,127 @@
// Copyright © 2024 Rangeproof Pty Ltd. All rights reserved.
//
// stringlint:disable
import Foundation
public enum TimeUnit: Equatable, CustomStringConvertible {
case nanoseconds(Double)
case microseconds(Double)
case milliseconds(Double)
case seconds(Double)
case minutes(Double)
case hours(Double)
case days(Double)
case weeks(Double)
var timeInterval: TimeInterval {
switch self {
case .nanoseconds(let value): return (value * 1e-9)
case .microseconds(let value): return (value * 1e-6)
case .milliseconds(let value): return (value * 1e-3)
case .seconds(let value): return value
case .minutes(let value): return (value * 60)
case .hours(let value): return (value * 3600)
case .days(let value): return (value * 86400)
case .weeks(let value): return (value * 604800)
}
}
var unit: Unit {
switch self {
case .nanoseconds: return .nanoseconds
case .microseconds: return .microseconds
case .milliseconds: return .milliseconds
case .seconds: return .seconds
case .minutes: return .minutes
case .hours: return .hours
case .days: return .days
case .weeks: return .weeks
}
}
public var description: String {
switch self {
case .nanoseconds(let value): return "\(value)\(unit)"
case .microseconds(let value): return "\(value)\(unit)"
case .milliseconds(let value): return "\(value)\(unit)"
case .seconds(let value): return "\(value)\(unit)"
case .minutes(let value): return "\(value)\(unit)"
case .hours(let value): return "\(value)\(unit)"
case .days(let value): return "\(value)\(unit)"
case .weeks(let value): return "\(value)\(unit)"
}
}
public init(_ other: TimeUnit, unit: Unit, resolution: Int? = nil) {
let otherSeconds: TimeInterval = other.timeInterval
let convertedValue: Double = {
switch unit {
case .nanoseconds: return (otherSeconds / 1e-9)
case .microseconds: return (otherSeconds / 1e-6)
case .milliseconds: return (otherSeconds / 1e-3)
case .seconds: return (otherSeconds)
case .minutes: return (otherSeconds / 60)
case .hours: return (otherSeconds / 3600)
case .days: return (otherSeconds / 86400)
case .weeks: return (otherSeconds / 604800)
}
}()
let result: Double = {
guard let resolution: Int = resolution else { return convertedValue }
guard resolution > 0 else { return floor(convertedValue) }
let targetResolution: TimeInterval = pow(10, TimeInterval(resolution))
return (floor(convertedValue * targetResolution) / targetResolution)
}()
switch unit {
case .nanoseconds: self = .nanoseconds(result)
case .microseconds: self = .microseconds(result)
case .milliseconds: self = .milliseconds(result)
case .seconds: self = .seconds(result)
case .minutes: self = .minutes(result)
case .hours: self = .hours(result)
case .days: self = .days(result)
case .weeks: self = .weeks(result)
}
}
}
// MARK: - TimeUnit.Unit
public extension TimeUnit {
enum Unit: CustomStringConvertible {
case nanoseconds
case microseconds
case milliseconds
case seconds
case minutes
case hours
case days
case weeks
public static var ns: Unit = .nanoseconds
public static var us: Unit = .microseconds //µs
public static var ms: Unit = .milliseconds
public static var s: Unit = .seconds
public static var m: Unit = .minutes
public static var h: Unit = .hours
public static var d: Unit = .days
public static var w: Unit = .weeks
public var description: String {
switch self {
case .nanoseconds: return "ns"
case .microseconds: return "µs"
case .milliseconds: return "ms"
case .seconds: return "s"
case .minutes: return "m"
case .hours: return "h"
case .days: return "d"
case .weeks: return "w"
}
}
}
}
Loading…
Cancel
Save