Crash when logging UserLocationOperation

[jshier]

I created a simple OperationQueue manager to find the current user location:

import Operations

typealias LocationCompletionHandler = (location: CLLocation) -> Void

class LocationManager : OperationQueue {
    private static let sharedManager = LocationManager()

    static var lastUserLocation: CLLocation?

    static func currentUserLocation(accuracy: CLLocationAccuracy = kCLLocationAccuracyThreeKilometers, completionHandler: LocationCompletionHandler) {
        let memoizingCompletionHandler: CLLocation -> Void = { location in
            lastUserLocation = location
        }

        let locationOperation = UserLocationOperation(accuracy: accuracy, completion: memoizingCompletionHandler)
        sharedManager.addOperation(locationOperation)
    }
}

Attempting to run it as so:

LocationManager.currentUserLocation { location in
    log("*** currentUserLocation: \(location) ***")
}

(I have my own log function)
Results in a crash in Logging.swift line 271. EXC_BAD_ACCESS (code=EXC_I386_GPFLT) Earlier in the call stack is LocationOperation.swift, line 141. This is on the main thread.

[danthorpe]

Hi @jshier - sorry about this. I must have missed something in the logging stuff I've added recently. It's almost 2am now, but will look into this tomorrow/later.

[danthorpe]

Hi @jshier is there any chance you could take a look at the Permissions example project on the branch in #122

I have added to the Location example your Manager class (more or less, you don't call the completion handler in the code above).

And when I run this I get...

User Location >>> MutuallyExclusive<CLLocationManager>
User Location: Initialized -> Pending
User Location: Pending -> EvaluatingConditions
User Location: EvaluatingConditions -> Ready
User Location: Ready -> Executing
User Location: did start
User Location updated last location: <+51.30969064,-0.12566690> +/- 65.00m (speed -1.00 mps /  course -1.00) @ 10/12/2015, 11:31:24 Greenwich Mean Time
got the location: <+51.30969064,-0.12566690> +/- 65.00m (speed -1.00 mps / course -1.00) @ > 10/12/2015, 11:31:24 Greenwich Mean Time
User Location: Executing -> Finishing
User Location: did finish with no errors.
User Location: Finishing -> Finished
User Location <<< MutuallyExclusive<CLLocationManager>

Without any crashes.

According to your stack trace, it's crashing when it's figuring out the operation name which is "User Location" from the above logs. I've got to pop out for a few hours, now, but hopefully this will help us figure out what is going on.

[jshier]

@danthorpe So it seems like this crash isn't really a crash but some sort of interaction with Operation's log and lldb. When I first wrote my LocationManager class I wasn't seeing the logging I expected as, as you found, I wasn't calling the actual completion handler. So I put a breakpoint on my LocationManager.currentUserLocation call point, hit continue, and it would break again in the logging call with the exception I posted. Without the debugger, there's no crash. Sorry, I didn't notice the distinction last night.

However, I do seem to occasionally be getting multiple calls to my completion handler. It was my understanding that UserLocationOperation should stop as soon as a location with the desired accuracy is found. Yet, I occasionally see this printed from a single currentUserLocation call:

2015-12-11 19:09:56.799: *** currentUserLocation: <+37.33233141,-122.03121860> +/- 5.00m (speed 0.00 mps / course -1.00) @ 12/11/15, 2:09:55 PM Eastern Standard Time ***
2015-12-11 19:10:03.445: *** currentUserLocation: <+37.33233141,-122.03121860> +/- 5.00m (speed 0.00 mps / course -1.00) @ 12/11/15, 2:10:03 PM Eastern Standard Time ***

Perhaps related to #123?

[jshier]

I take that back. I'm seeing the exception even with breakpoints disabled (but I'm still in debugging mode). I'll try your sample next.

[jshier]

Yes, I get the same exception with your example project. Here's the output before it crashes on line 141 of LocationOperation.swift. This is Xcode 7.2 with iOS 9.2 in the iPhone 6s simulator on 10.11.2.

User Location >>> MutuallyExclusive<CLLocationManager>
User Location: Initialized -> Pending
User Location: Pending -> EvaluatingConditions
User Location: EvaluatingConditions -> Ready
User Location: Ready -> Executing
User Location: did start
User Location updated last location: <+37.33233141,-122.03121860> +/- 5.00m (speed 0.00 mps / course -1.00) @ 12/11/15, 3:06:26 PM Eastern Standard Time
got the location: <+37.33233141,-122.03121860> +/- 5.00m (speed 0.00 mps / course -1.00) @ 12/11/15, 3:06:26 PM Eastern Standard Time
User Location: Executing -> Finishing
User Location: did finish with no errors.
User Location: Finishing -> Finished
User Location <<< MutuallyExclusive<CLLocationManager>

As an aside, is there an easy way to completely disable logging for the library? I don't usually need it as I've built my own logging OperationObserver.

[danthorpe]

@jshier - just going through your comments here...

I don't think this is related to #123 - that is only an issue with BlockOperation and the _UserLocationOperation subclasses Operation, and the completion block it takes as an argument is not the same as NSOperation's completionBlock property.

One thing that might be relevant is that I typically never test CLLocation stuff using the simulator, so I was doing my tests with a real device. Not sure if that would make a difference though? I'm currently updating my test device to 9.2....

Aside - Regarding the logging - I'm going to do a ticket to turn the log message into an @autoclosure which will nullify it's usage if you're using your own logging observer. Will add an enabled switch at the same time. Internally, there is the option to set global severity threshold too, but I've not made this public yet. So, will refine this a bit more.

Part of my intention with the built in logger in Operation was so that an operation would be able to perform logging in cases other than started/produced/finished. Which I think can be a bit more useful when debugging what is happening in custom operations. While also allow consumers to define their own logger - e.g. if you want to send stuff to files/buffers/services. So, I would be interested to hear if that is not something you'd consider useful, or alternatively, what you have in your custom logging observer. I was thinking of eventually removing the LoggingObserver which ships with the framework.

[danthorpe]

Also... this kind of memoizing manager sounds pretty useful - perhaps something which could/should be added to Operations?

[jshier]

Possibly. There's additional functionality it needs to be truly useful but CLLocationManager has always been a pain point for iOS developers.

[danthorpe]

Okay, running the Permissions example works for me in the simulator - Xcode 7.2, iOS 9.2 on 10.11.2 - no exceptions, no crashes, and only one location.

Do you have any breakpoints setup?

Could this be because you have a log function and the operation has a log property - there is no reason why that would cause an issue right?

[danthorpe]

Ah! I think I've managed to re-produce it, while working on #126.

Is this sort of like the crash you're seeing?

But it is still a little tricky to reproduce - only managed it once. If this is the crash/stacktrace you're seeing is it consistent / every time?

[danthorpe]

Hi @jshier there have been some improvements to how the logging works, including use of @autoclosure, refactor of the messages (to avoid accessing self), exposure of global severity level and enabled flags.

I'm pretty sure that the bug was due to accessing .operationName in the log message inside UserLocationOperation which obviously meant that the operation was being captured by the logger and is generally not what we'd want to do (I know that in theory ARC should handle this for us), but on reflection it was just a poor design decision. So, now the operationName is set on the LoggerType when it is accessed and the default logger will include the name in the info it prints out.

Other changes, you can do this:

// Set the global log level like this
LogManager.severity = .Notice

// Disable built in logging entirely like this:
LogManager.enabled = false

If you can still re-produce the crash on development, then... I'll circle back to look even more closely at what is going on. I've found it very hard to reproduce the crash before the change, and not at all after these changes.

[jshier]

Looks good. I'm able to use my LocationManager in both the Permissions demo app and my app as well, when building against the development branch.

[danthorpe]

Okay, I'm going to close this issue now. 🙂