CareKit icon indicating copy to clipboard operation
CareKit copied to clipboard

Don't go east!

Open advatar opened this issue 3 years ago • 11 comments

I noticed that whenever I fly or set the timezone forward like going east I get this crash:


#0	0x0000000186877cf4 in _swift_runtime_on_report ()
#1	0x00000001868f7e60 in _swift_stdlib_reportFatalErrorInFile ()
#2	0x000000018652d23c in closure #1 in closure #1 in closure #1 in _assertionFailure(_:_:file:line:flags:) ()
#3	0x000000018652cfdc in closure #1 in closure #1 in _assertionFailure(_:_:file:line:flags:) ()
#4	0x000000018652c8d0 in _assertionFailure(_:_:file:line:flags:) ()
#5	0x000000018650e6f4 in Array.subscript.modify ()
#6	0x000000010098f9b0 in OCKReadOnlyEventStore<>.join(task:with:and:) at /Users/johansellstrom/Library/Developer/Xcode/DerivedData/Vagus-dawdpcwkilywlafthnhgqukawkma/SourcePackages/checkouts/CareKit/CareKitStore/CareKitStore/Protocols/Events/OCKEventStore.swift:217
#7	0x000000010098ecec in closure #1 in OCKReadOnlyEventStore<>.fetchEvents(task:query:previousEvents:callbackQueue:completion:) at /Users/johansellstrom/Library/Developer/Xcode/DerivedData/Vagus-dawdpcwkilywlafthnhgqukawkma/SourcePackages/checkouts/CareKit/CareKitStore/CareKitStore/Protocols/Events/OCKEventStore.swift:148
#8	0x00000001009940a4 in partial apply for closure #1 in OCKReadOnlyEventStore<>.fetchEvents(task:query:previousEvents:callbackQueue:completion:) ()
#9	0x00000001008fa56c in closure #3 in closure #1 in OCKStore.fetchOutcomes(query:callbackQueue:completion:) at /Users/johansellstrom/Library/Developer/Xcode/DerivedData/Vagus-dawdpcwkilywlafthnhgqukawkma/SourcePackages/checkouts/CareKit/CareKitStore/CareKitStore/CoreData/OCKStore+Outcomes.swift:48
#10	0x00000001008f0408 in thunk for @escaping @callee_guaranteed () -> () ()
#11	0x0000000102f486a0 in _dispatch_call_block_and_release ()
#12	0x0000000102f4a380 in _dispatch_client_callout ()
#13	0x0000000102f5a864 in _dispatch_main_queue_callback_4CF ()
#14	0x0000000181b0dcd4 in __CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ ()
#15	0x0000000181ac7eac in __CFRunLoopRun ()
#16	0x0000000181adb3b8 in CFRunLoopRunSpecific ()
#17	0x000000019db0b38c in GSEventRunModal ()
#18	0x000000018447bb60 in -[UIApplication _run] ()
#19	0x00000001841fa8b8 in UIApplicationMain ()
#20	0x0000000100569058 in main at /Users/johansellstrom/dev/advatar/VagusOriginal/OCKSample/App/AppDelegate.swift:120
#21	0x0000000102e1da24 in start ()
Enqueued from NSManagedObjectContext 0x28065dc70 (Thread 7) Queue : NSManagedObjectContext 0x28065dc70 (serial)
#0	0x0000000102f4f0f8 in dispatch_async ()
#1	0x000000019b607a3c in _swift_dispatch_async ()
#2	0x000000019b60847c in OS_dispatch_queue.async(group:qos:flags:execute:) ()
#3	0x00000001008f882c in closure #1 in OCKStore.fetchOutcomes(query:callbackQueue:completion:) at /Users/johansellstrom/Library/Developer/Xcode/DerivedData/Vagus-dawdpcwkilywlafthnhgqukawkma/SourcePackages/checkouts/CareKit/CareKitStore/CareKitStore/CoreData/OCKStore+Outcomes.swift:48
#4	0x00000001008f0408 in thunk for @escaping @callee_guaranteed () -> () ()
#5	0x00000001890de37c in developerSubmittedBlockToNSManagedObjectContextPerform ()
#6	0x0000000102f4a380 in _dispatch_client_callout ()
#7	0x0000000102f5250c in _dispatch_lane_serial_drain ()
#8	0x0000000102f5325c in _dispatch_lane_invoke ()
#9	0x0000000102f5fdec in _dispatch_workloop_worker_thread ()
#10	0x00000001f2bee0f4 in _pthread_wqthread ()
#11	0x00000001f2bede94 in start_wqthread ()

This can be traced like

open func fetchOutcomes(query: OCKOutcomeQuery = OCKOutcomeQuery(), callbackQueue: DispatchQueue = .main,
                            completion: @escaping (Result<[OCKOutcome], OCKStoreError>) -> Void) {
        context.perform {
            do {
                let request = NSFetchRequest<OCKCDOutcome>(entityName: String(describing: OCKCDOutcome.self))
                request.fetchLimit = query.limit ?? 0
                request.fetchOffset = query.offset
                request.sortDescriptors = self.buildSortDescriptors(for: query)
                request.predicate = self.buildPredicate(for: query)
                let objects = try self.context.fetch(request)
                let notTombstoned = objects.filter { !$0.newestVersionIsTombstone() }
                let outcomes = notTombstoned.map { $0.makeOutcome() }

                callbackQueue.async { completion(.success(outcomes)) }
            } catch {
                self.context.rollback()
                let reason = "Failed to fetch outcomes for query. \(error.localizedDescription)"
                callbackQueue.async { completion(.failure(.fetchFailed(reason: reason))) }
            }
        }
    }
 

Which goes to

    private func fetchEvent(withTaskVersion taskVersionUUID: UUID, occurrenceIndex: Int,
                            callbackQueue: DispatchQueue, completion: @escaping OCKResultClosure<OCKEvent<Task, Outcome>>) {
        fetchTask(withVersion: taskVersionUUID, callbackQueue: callbackQueue, completion: { (result: Result<Task, OCKStoreError>) in
            switch result {
            case .failure(let error): completion(.failure(.fetchFailed(reason: "Failed to fetch task. \(error.localizedDescription)")))
            case .success(let task):
                guard let scheduleEvent = task.schedule.event(forOccurrenceIndex: occurrenceIndex) else {
                    completion(.failure(.fetchFailed(reason: "Invalid occurrence \(occurrenceIndex) for task with version ID: \(taskVersionUUID)")))
                    return
                }
                let early = scheduleEvent.start.addingTimeInterval(-1)
                let late = scheduleEvent.end.addingTimeInterval(1)
                var query = OCKOutcomeQuery(dateInterval: DateInterval(start: early, end: late))
                query.taskUUIDs = [taskVersionUUID]
                self.fetchOutcomes(query: query, callbackQueue: callbackQueue, completion: { result in
                    switch result {
                    case .failure(let error): completion(.failure(.fetchFailed(reason: "Couldn't find outcome. \(error.localizedDescription)")))
                    case .success(let outcomes):
                        let matchingOutcome = outcomes.first(where: { $0.taskOccurrenceIndex == occurrenceIndex })
                        let event = OCKEvent(task: task, outcome: matchingOutcome, scheduleEvent: scheduleEvent)
                        completion(.success(event))
                    }
                })
            }
        })
    }

And finally it crashes here:

 private func join(task: Task, with outcomes: [Outcome], and scheduleEvents: [OCKScheduleEvent]) -> [OCKEvent<Task, Outcome>] {
        guard !scheduleEvents.isEmpty else { return [] }
        let offset = scheduleEvents[0].occurrence
        var events = scheduleEvents.map { OCKEvent<Task, Outcome>(task: task, outcome: nil, scheduleEvent: $0) }
        for outcome in outcomes {
            events[outcome.taskOccurrenceIndex - offset].outcome = outcome
        }
        return events
    }

The problem is the index here events[outcome.taskOccurrenceIndex - offset].

advatar avatar Sep 30 '21 12:09 advatar

As soon as I reset the TZ it works again

advatar avatar Sep 30 '21 12:09 advatar

Actually, going west seems equally bad. Same crash.

advatar avatar Sep 30 '21 12:09 advatar

More clues from this thread

#0	0x00000001b90fe48c in _kernelrpc_mach_vm_purgable_control_trap ()
#1	0x00000001b90fef6c in mach_vm_purgable_control ()
#2	0x00000001a0a6ae1c in ___lldb_unnamed_symbol63$$libsqlite3.dylib ()
#3	0x00000001a0b4f69c in ___lldb_unnamed_symbol1018$$libsqlite3.dylib ()
#4	0x00000001a0a6a94c in ___lldb_unnamed_symbol62$$libsqlite3.dylib ()
#5	0x00000001a0b00530 in ___lldb_unnamed_symbol508$$libsqlite3.dylib ()
#6	0x00000001a0b0affc in ___lldb_unnamed_symbol595$$libsqlite3.dylib ()
#7	0x00000001a0a94530 in ___lldb_unnamed_symbol94$$libsqlite3.dylib ()
#8	0x00000001a0a9e800 in ___lldb_unnamed_symbol127$$libsqlite3.dylib ()
#9	0x00000001a0a8528c in ___lldb_unnamed_symbol92$$libsqlite3.dylib ()
#10	0x00000001a0a838f0 in sqlite3_step ()
#11	0x00000001890e89f4 in _execute ()
#12	0x00000001890ea248 in -[NSSQLiteConnection execute] ()
#13	0x00000001890eed38 in newFetchedRowsForFetchPlan_MT ()
#14	0x00000001891083bc in _executeNewValuesForRelationshipFaultRequest ()
#15	0x000000018912e808 in -[NSSQLRelationshipFaultRequestContext executeRequestCore:] ()
#16	0x00000001891aee94 in -[NSSQLStoreRequestContext executeRequestUsingConnection:] ()
#17	0x000000018910f044 in __52-[NSSQLDefaultConnectionManager handleStoreRequest:]_block_invoke ()
#18	0x00000001890e093c in __37-[NSSQLiteConnection performAndWait:]_block_invoke ()
#19	0x0000000103946380 in _dispatch_client_callout ()
#20	0x00000001039578b0 in _dispatch_lane_barrier_sync_invoke_and_complete ()
#21	0x00000001890dea78 in -[NSSQLiteConnection performAndWait:] ()
#22	0x00000001890eb984 in -[NSSQLDefaultConnectionManager handleStoreRequest:] ()
#23	0x00000001890fe7a0 in -[NSSQLCoreDispatchManager routeStoreRequest:] ()
#24	0x00000001890f4640 in -[NSSQLCore dispatchRequest:withRetries:] ()
#25	0x0000000189161038 in -[NSSQLCore _newValuesForRelationship:forObjectWithID:withContext:error:] ()
#26	0x0000000189127904 in -[NSSQLCore newValueForRelationship:forObjectWithID:withContext:error:] ()
#27	0x0000000189123a7c in __110-[NSPersistentStoreCoordinator(_NSInternalMethods) newValueForRelationship:forObjectWithID:withContext:error:]_block_invoke ()
#28	0x00000001890e955c in -[NSPersistentStoreCoordinator _routeLightweightBlock:toStore:] ()
#29	0x00000001891b557c in -[NSPersistentStoreCoordinator(_NSInternalMethods) newValueForRelationship:forObjectWithID:withContext:error:] ()
#30	0x000000018911818c in -[NSFaultHandler retainedFulfillAggregateFaultForObject:andRelationship:withContext:] ()
#31	0x0000000189182ab8 in -[_NSFaultingMutableSet willReadWithContents:] ()
#32	0x00000001891b77d8 in -[_NSFaultingMutableSet count] ()
#33	0x00000001866b5fb4 in _stdlib_NSSet_allObjects(_:) ()
#34	0x00000001866a8f18 in Set.startIndex.getter ()
#35	0x00000001866aa524 in protocol witness for Collection.startIndex.getter in conformance Set<τ_0_0> ()
#36	0x000000018652a180 in Collection.first.getter ()
#37	0x00000001013bab10 in OCKCDVersionedObject.firstVersion() at /Users/johansellstrom/Library/Developer/Xcode/DerivedData/Vagus-dawdpcwkilywlafthnhgqukawkma/SourcePackages/checkouts/CareKit/CareKitStore/CareKitStore/CoreData/OCKCDVersionedObject.swift:159
#38	0x00000001013ba730 in OCKCDVersionedObject.nonConflictedVersions() at /Users/johansellstrom/Library/Developer/Xcode/DerivedData/Vagus-dawdpcwkilywlafthnhgqukawkma/SourcePackages/checkouts/CareKit/CareKitStore/CareKitStore/CoreData/OCKCDVersionedObject.swift:177
#39	0x00000001013ba544 in OCKCDVersionedObject.newestVersionIsTombstone() at /Users/johansellstrom/Library/Developer/Xcode/DerivedData/Vagus-dawdpcwkilywlafthnhgqukawkma/SourcePackages/checkouts/CareKit/CareKitStore/CareKitStore/CoreData/OCKCDVersionedObject.swift:126
#40	0x00000001013c63cc in closure #1 in closure #1 in OCKStore.fetchOutcomes(query:callbackQueue:completion:) at /Users/johansellstrom/Library/Developer/Xcode/DerivedData/Vagus-dawdpcwkilywlafthnhgqukawkma/SourcePackages/checkouts/CareKit/CareKitStore/CareKitStore/CoreData/OCKStore+Outcomes.swift:45
#41	0x00000001013c6400 in thunk for @callee_guaranteed (@guaranteed OCKCDOutcome) -> (@unowned Bool, @error @owned Error) ()
#42	0x00000001013c919c in partial apply for thunk for @callee_guaranteed (@guaranteed OCKCDOutcome) -> (@unowned Bool, @error @owned Error) ()
#43	0x0000000186529560 in _ArrayProtocol.filter(_:) ()
#44	0x00000001013c46c4 in closure #1 in OCKStore.fetchOutcomes(query:callbackQueue:completion:) at /Users/johansellstrom/Library/Developer/Xcode/DerivedData/Vagus-dawdpcwkilywlafthnhgqukawkma/SourcePackages/checkouts/CareKit/CareKitStore/CareKitStore/CoreData/OCKStore+Outcomes.swift:45
#45	0x00000001013bc408 in thunk for @escaping @callee_guaranteed () -> () ()
#46	0x00000001890de37c in developerSubmittedBlockToNSManagedObjectContextPerform ()
#47	0x0000000103946380 in _dispatch_client_callout ()
#48	0x000000010394e50c in _dispatch_lane_serial_drain ()
#49	0x000000010394f25c in _dispatch_lane_invoke ()
#50	0x000000010395bdec in _dispatch_workloop_worker_thread ()
#51	0x00000001f2bee0f4 in _pthread_wqthread ()

The traceback in code
    let notTombstoned = objects.filter { !$0.newestVersionIsTombstone() }

....

 func newestVersionIsTombstone() -> Bool {
      let resolved = **nonConflictedVersions**()
      let last = resolved.last
      let isTombstone = last?.deletedDate != nil
      return isTombstone
  }

private func nonConflictedVersions() -> [OCKCDVersionedObject] {
    var current = **firstVersion()**
    var balance = 0
    var versions = [current]

    while let next = current.next.first {

        let incoming = next.previous.count
        let outgoing = next.next.count
        balance = outgoing - incoming

        // Include less than zero because the last node has no outgoing edge
        if balance <= 0 {
            versions.append(next)
        }

        current = next
    }

    return versions
}

/// Find the first version of this object via a depth-first-search for a node with no previous nodes.
private func firstVersion() -> OCKCDVersionedObject {

    guard let prev = previous.**first** else {
        return self
    }

    let first = prev.firstVersion()
    return first
}

advatar avatar Sep 30 '21 13:09 advatar

In my case I have outcome.taskOccurrenceIndex - offset = 299-300 = -1

advatar avatar Sep 30 '21 15:09 advatar

Curious to know if anyone else is experiencing this? It is very easy to test, just change the timezone.

advatar avatar Oct 02 '21 17:10 advatar

@erik-apple Can you help? Travelling users are reporting this.

advatar avatar Oct 05 '21 16:10 advatar

I'm sorry to hear users are seeing crashes! Thanks for including all of this debug information, I'll take a peek now and see if I can spot the issue.

gavirawson-apple avatar Oct 05 '21 16:10 gavirawson-apple

Maybe be a little defensive here:


for outcome in outcomes {
            events[outcome.taskOccurrenceIndex - offset].outcome = outcome
        }
=>
for outcome in outcomes {
            if (outcome.taskOccurrenceIndex - offset>=0) {
            events[outcome.taskOccurrenceIndex - offset].outcome = outcome
            }
        }

I guess I could do so in my own fork. What would the effect be of this, missing outcomes I guess?

advatar avatar Oct 06 '21 11:10 advatar

Yeah, I would guess that there will be missing outcomes, and there's likely another underlying issue lurking around. I haven't been able to reproduce the issue on my end, can you provide the steps to reproduce the moment when you see the crash? Some helpful notes to include are:

  1. What date and time are outcomes saved in the store?
  2. When is the timezone changed? What are the old and new timezones?
  3. For what date interval are events fetched when you see the crash?

gavirawson-apple avatar Oct 06 '21 17:10 gavirawson-apple

  1. Don't know how to get that.
  2. It does not matter, just change to any new TZ
  3. I am just using the OCKDailyPageViewController so it is for "Today" (which is another interval that is suddenly different)

advatar avatar Oct 11 '21 17:10 advatar

This prevents the crash, but why is offset off by 1 when the TimeZone changed?

private func join(task: Task, with outcomes: [Outcome], and scheduleEvents: [OCKScheduleEvent]) -> [OCKEvent<Task, Outcome>] {
        guard !scheduleEvents.isEmpty else { return [] }
        let offset = scheduleEvents[0].occurrence
        var events = scheduleEvents.map { OCKEvent<Task, Outcome>(task: task, outcome: nil, scheduleEvent: $0) }
        for outcome in outcomes {
            if outcome.taskOccurrenceIndex - offset >= 0 {
                events[outcome.taskOccurrenceIndex - offset].outcome = outcome
            } else {
                print("ERROR: outcome.taskOccurrenceIndex \(outcome.taskOccurrenceIndex) offset \(offset)")
            }
        }
        return events
    }

advatar avatar Oct 22 '21 15:10 advatar