425 more logging only first trackable added comes online when stationary

.github/workflows/check.yml

@@ -48,15 +48,19 @@ jobs:
 
   check-log-parser:
     runs-on: macos-latest
-    defaults:
-      run:
-        working-directory: Tools/LogParser
     steps:
       - uses: actions/checkout@v2
         with:
           submodules: recursive
 
       - name: Run LogParser tests
         run: swift test
-      - name: Build LogParser command-line example app
-        run: swift build --target CommandLineExample
+        working-directory: Tools/Library/LogParser
+
+      - name: Build LogParserExample app
+        run: swift build
+        working-directory: Tools/Library/LogParserExample
+
+      - name: Build AnalyzeLocationEventFrequencies app
+        run: swift build
+        working-directory: Tools/Analysis/AnalyzeLocationEventFrequencies

Examples/PublisherExampleSwiftUI/PublisherExampleSwiftUI/Logger/PublisherLogger.swift

@@ -10,18 +10,28 @@ class PublisherLogger: AblyAssetTrackingCore.LogHandler {
     }
 
     func logMessage(level: LogLevel, message: String, error: Error?) {
-        let errorString = error?.localizedDescription
-        switch level {
-        case .verbose:
-            logger.log(level: .trace, "\(message). \(errorString ?? "")")
-        case .info:
-            logger.log(level: .info, "\(message). \(errorString ?? "")")
-        case .debug:
-            logger.log(level: .debug, "\(message). \(errorString ?? "")")
-        case .warn:
-            logger.log(level: .warning, "\(message). \(errorString ?? "")")
-        case .error:
-            logger.log(level: .error, "\(message). \(errorString ?? "")")
+        let prefix: String
+
+        if let error = error {
+            // The LogParser library needs to be able to extract the error description from the log message; for this reason we emit its length
+            let errorDescription = error.localizedDescription
+            prefix = "[error(len:\(errorDescription.count)): \(errorDescription)] "
+        } else {
+            prefix = "[noError] "
+        }
+
+        logger.log(level: level.swiftLogLevel, "\(prefix)\(message)")
+    }
+}
+
+private extension LogLevel {
+    var swiftLogLevel: Logger.Level {
+        switch self {
+        case .verbose: return .trace
+        case .info: return .info
+        case .debug: return .debug
+        case .warn: return .warning
+        case .error: return .error
         }
     }
 }

Examples/PublisherExampleSwiftUI/PublisherExampleSwiftUI/Model/ObservablePublisher.swift

@@ -1,9 +1,11 @@
 import Combine
 import AblyAssetTrackingPublisher
 import Foundation
+import Logging
 
 class ObservablePublisher: ObservableObject {
     private let publisher: AblyAssetTrackingPublisher.Publisher
+    private let logger: Logger?
     let configInfo: PublisherConfigInfo
     let locationHistoryDataHandler: LocationHistoryDataHandlerProtocol?
 
@@ -22,11 +24,12 @@ class ObservablePublisher: ObservableObject {
     @Published private(set) var lastError: ErrorInformation?
 
     // After initialising an ObservablePublisher instance, you need to manually set the publisher’s delegate to the created instance.
-    init(publisher: AblyAssetTrackingPublisher.Publisher, configInfo: PublisherConfigInfo, locationHistoryDataHandler: LocationHistoryDataHandlerProtocol? = nil) {
+    init(publisher: AblyAssetTrackingPublisher.Publisher, configInfo: PublisherConfigInfo, locationHistoryDataHandler: LocationHistoryDataHandlerProtocol? = nil, logger: Logger? = nil) {
         self.publisher = publisher
         self.configInfo = configInfo
         self.routingProfile = publisher.routingProfile
         self.locationHistoryDataHandler = locationHistoryDataHandler
+        self.logger = logger
     }
 
     func stop(completion: @escaping ResultHandler<Void>) {
@@ -89,6 +92,19 @@ extension ObservablePublisher: PublisherDelegate {
     }
 
     func publisher(sender: AblyAssetTrackingPublisher.Publisher, didFinishRecordingLocationHistoryData locationHistoryData: LocationHistoryData) {
+        if SettingsModel.shared.logLocationHistoryJSON {
+            do {
+                let jsonData = try JSONEncoder().encode(locationHistoryData)
+                if let jsonString = String(data: jsonData, encoding: .utf8) {
+                    logger?.log(level: .debug, "Received location history data: \(jsonString)")
+                } else {
+                    logger?.log(level: .error, "Failed to convert location history data to string")
+                }
+            } catch {
+                logger?.log(level: .error, "Failed to serialize location history data to JSON: \(error.localizedDescription)")
+            }
+        }
+
         locationHistoryDataHandler?.handleLocationHistoryData(locationHistoryData)
     }
 

Examples/PublisherExampleSwiftUI/PublisherExampleSwiftUI/Model/SettingsModel.swift

@@ -67,6 +67,15 @@ class SettingsModel {
         }
     }
 
+    var logLocationHistoryJSON: Bool {
+        get {
+            UserDefaults.standard.bool(forKey: "logLocationHistoryJSON")
+        }
+        set {
+            UserDefaults.standard.set(newValue, forKey: "logLocationHistoryJSON")
+        }
+    }
+
     var vehicleProfile: VehicleProfile {
         get {
             guard let profile: VehicleProfile = UserDefaults.standard.get("vehicleProfile") else {

Examples/PublisherExampleSwiftUI/PublisherExampleSwiftUI/View/Settings/SettingsView.swift

@@ -45,6 +45,15 @@ struct SettingsView: View {
             } header: {
                 Text("Other settings")
             }
+
+            Section {
+                Toggle(isOn: $viewModel.logLocationHistoryJSON) {
+                    Text("Log location history JSON")
+                    Text("Causes the app to emit a `debug` level log message when a `LocationHistoryData` is received from the Asset Tracking SDK. The log message will contain a JSON serialization of this history data.")
+                }
+            } header: {
+                Text("Developer settings")
+            }
         }
         .listStyle(.grouped)
         .navigationBarTitle("Settings")

Examples/PublisherExampleSwiftUI/PublisherExampleSwiftUI/ViewModel/CreatePublisherViewModel.swift

@@ -136,7 +136,7 @@ class CreatePublisherViewModel: ObservableObject {
 
         let configInfo = ObservablePublisher.PublisherConfigInfo(areRawLocationsEnabled: areRawLocationsEnabled, constantResolution: constantResolution)
 
-        let observablePublisher = ObservablePublisher(publisher: publisher, configInfo: configInfo, locationHistoryDataHandler: locationHistoryDataHandler)
+        let observablePublisher = ObservablePublisher(publisher: publisher, configInfo: configInfo, locationHistoryDataHandler: locationHistoryDataHandler, logger: logger)
         publisher.delegate = observablePublisher
 
         return observablePublisher

Examples/PublisherExampleSwiftUI/PublisherExampleSwiftUI/ViewModel/SettingsViewModel.swift

@@ -9,6 +9,12 @@ class SettingsViewModel: ObservableObject {
         }
     }
 
+    @Published var logLocationHistoryJSON: Bool = SettingsModel.shared.logLocationHistoryJSON {
+        didSet {
+            SettingsModel.shared.logLocationHistoryJSON = logLocationHistoryJSON
+        }
+    }
+
     @Published var defaultResolutionMinimumDisplacement: String  = "\(SettingsModel.shared.defaultResolution.minimumDisplacement)"
     @Published var defaultResolutionDesiredInterval: String  = "\(SettingsModel.shared.defaultResolution.desiredInterval)"
 

Examples/SubscriberExample/Sources/Screens/Logging/SubscriberLogger.swift

@@ -10,18 +10,28 @@ class SubscriberLogger: AblyAssetTrackingCore.LogHandler {
     }
 
     func logMessage(level: LogLevel, message: String, error: Error?) {
-        let errorString = error?.localizedDescription
-        switch level {
-        case .verbose:
-            logger.log(level: .trace, "\(message). \(errorString ?? "")")
-        case .info:
-            logger.log(level: .info, "\(message). \(errorString ?? "")")
-        case .debug:
-            logger.log(level: .debug, "\(message). \(errorString ?? "")")
-        case .warn:
-            logger.log(level: .warning, "\(message). \(errorString ?? "")")
-        case .error:
-            logger.log(level: .error, "\(message). \(errorString ?? "")")
+        let prefix: String
+
+        if let error = error {
+            // The LogParser library needs to be able to extract the error description from the log message; for this reason we emit its length
+            let errorDescription = error.localizedDescription
+            prefix = "[error(len:\(errorDescription.count)): \(errorDescription)] "
+        } else {
+            prefix = "[noError] "
+        }
+
+        logger.log(level: level.swiftLogLevel, "\(prefix)\(message)")
+    }
+}
+
+private extension LogLevel {
+    var swiftLogLevel: Logger.Level {
+        switch self {
+        case .verbose: return .trace
+        case .info: return .info
+        case .debug: return .debug
+        case .warn: return .warning
+        case .error: return .error
         }
     }
 }

Sources/AblyAssetTrackingPublisher/DefaultPublisher.swift

@@ -263,12 +263,18 @@ extension DefaultPublisher {
         ablyPublisher.subscribeForChannelStateChange(trackable: event.trackable)
 
         trackables.insert(event.trackable)
-        //Start updating location only after the first trackable
         if (trackables.count == 1){
+            //Start updating location only after the first trackable
             locationService.startRecordingLocation()
             locationService.startUpdatingLocation()
+        } else {
+            // We do this to increase the chances of receiving an enhanced location update for this trackable, so that the trackable can move into the online connection state as quickly as possible (see the hasSentAtLeastOneLocation check inside handleConnectionStateChange).
+
+            // If we did not do this, then (since startUpdatingLocation has already been called on the location service) in the case of a slowly-moving or stationary device, the trackable would not move into the online connection state until the device had moved a distance deemed worthy (by the resolution policy) of a new location update.
+            locationService.requestLocationUpdate()
         }
         resolveResolution(trackable: event.trackable)
+
         hooks.trackables?.onTrackableAdded(trackable: event.trackable)
         event.completion.handleSuccess()
         duplicateTrackableGuard.finishAddingTrackableWithId(event.trackable.id, result: .success)

Sources/AblyAssetTrackingPublisher/Services/DefaultLocationService.swift

@@ -72,6 +72,17 @@ class DefaultLocationService: LocationService {
         locationManager.systemLocationManager.stopUpdatingLocation()
     }
 
+    func requestLocationUpdate() {
+        /*
+         From reading the ``CLLocationManager/startUpdatingLocation`` documentation, this seems to be the only programmatic way to provoke it into emitting a location event:
+
+        > Calling this method several times in succession does not automatically result in new events being generated. Calling stopUpdatingLocation() in between, however, does cause a new initial event to be sent the next time you call this method.
+        */
+        logHandler?.debug(message: "Received requestLocationUpdate", error: nil)
+        locationManager.systemLocationManager.stopUpdatingLocation()
+        locationManager.systemLocationManager.startUpdatingLocation()
+    }
+
     enum LocationHistoryTemporaryStorageConfiguration {
         private static let fileManager = FileManager.default
 
@@ -165,6 +176,7 @@ extension DefaultLocationService: PassiveLocationManagerDelegate {
     }
 
     func passiveLocationManager(_ manager: PassiveLocationManager, didUpdateLocation location: CLLocation, rawLocation: CLLocation) {
+        logHandler?.debug(message: "passiveLocationManager.didUpdateLocation", error: nil)
         delegate?.locationService(sender: self, didUpdateRawLocationUpdate: RawLocationUpdate(location: rawLocation.toLocation()))
         delegate?.locationService(sender: self, didUpdateEnhancedLocationUpdate: EnhancedLocationUpdate(location: location.toLocation()))
     }

Sources/AblyAssetTrackingPublisher/Services/LocationService.swift

@@ -19,4 +19,6 @@ protocol LocationService: AnyObject {
     func startRecordingLocation()
     func stopRecordingLocation(completion: @escaping ResultHandler<LocationRecordingResult?>)
     func changeLocationEngineResolution(resolution: Resolution)
+    /// Requests that the location service emit a new location update as soon as possible. The location service will make a best effort to ensure that, shortly after this method is called, its delegate receives a ``LocationServiceDelegate/locationService(sender:didUpdateRawLocationUpdate)`` and ``LocationServiceDelegate/locationService(sender:didUpdateEnhancedLocationUpdate)`` event.
+    func requestLocationUpdate()
 }

Tests/PublisherTests/DefaultPublisher/DefaultPublisherTests.swift

@@ -289,6 +289,39 @@ class DefaultPublisherTests: XCTestCase {
         XCTAssertEqual(publisher.activeTrackable, trackable)
     }
 
+    func testAddSecondTrackable_callsRequestLocationUpdateOnLocationService() {
+        ablyPublisher.connectCompletionHandler = { completion in  completion?(.success) }
+        let expectation = XCTestExpectation()
+        expectation.expectedFulfillmentCount = 2
+
+        // When tracking a trackable
+        publisher.add(trackable: trackable) { result in
+            switch result {
+            case .success:
+                expectation.fulfill()
+            case .failure:
+                XCTFail("Failure callback shouldn't be called")
+            }
+        }
+
+        // It should not yet have called requestLocationUpdate on the location service
+        XCTAssertFalse(locationService.requestLocationUpdateCalled)
+
+        // And then adding another trackable
+        publisher.add(trackable: Trackable(id: "TestAddedTrackableId1")) { result in
+            switch result {
+            case .success:
+                expectation.fulfill()
+            case .failure:
+                XCTFail("Failure callback shouldn't be called")
+            }
+        }
+        wait(for: [expectation], timeout: 5.0)
+
+        // It should call requestLocationUpdate on the location service
+        XCTAssertTrue(locationService.requestLocationUpdateCalled)
+    }
+
     func testAdd_track_error() {
         let errorInformation = ErrorInformation(type: .publisherError(errorMessage: "Test AblyPublisherService error"))
         ablyPublisher.connectCompletionHandler = { completion in  completion?(.failure(errorInformation)) }

Tests/Support/AblyAssetTrackingPublisherTesting/Mocks/MockLocationService.swift

@@ -40,4 +40,9 @@ public class MockLocationService: LocationService {
         stopRecordingLocationParamCompletion = completion
         stopRecordingLocationCallback?(completion)
     }
+
+    public var requestLocationUpdateCalled = false
+    public func requestLocationUpdate() {
+        requestLocationUpdateCalled = true
+    }
 }

Tools/Analysis/AnalyzeLocationEventFrequencies/Package.swift

@@ -0,0 +1,24 @@
+// swift-tools-version: 5.7
+// The swift-tools-version declares the minimum version of Swift required to build this package.
+
+import PackageDescription
+
+let package = Package(
+    name: "AnalyzeLocationEventFrequencies",
+    platforms: [
+        .macOS(.v12)
+    ],
+    dependencies: [
+        .package(url: "https://github.com/apple/swift-argument-parser", from: "1.2.0"),
+        .package(path: "../../Library/LogParser")
+    ],
+    targets: [
+        .executableTarget(
+            name: "AnalyzeLocationEventFrequencies",
+            dependencies: [
+                .product(name: "LogParser", package: "LogParser"),
+                .product(name: "ArgumentParser", package: "swift-argument-parser")
+            ]
+        ),
+    ]
+)