Root causing our "weird" crash logs

[cmsj]

So, this is not the first time I've decided I'm determined to get to the bottom of why we always have some "weird" crash reports, and it probably won't be the last time, but I'd like to discuss it again anyway.

Tagging @asmagill for his excellent thoughts.

Here are the "weird" crash reports received thus far for 0.9.84:

• https://sentry.io/organizations/hammerspoon/issues/2264596621/?project=5220516&query=is%3Aunresolved+release%3Alatest&statsPeriod=14d
• https://sentry.io/organizations/hammerspoon/issues/2264749660/?project=5220516&query=is%3Aunresolved+release%3Alatest&statsPeriod=14d
• https://sentry.io/organizations/hammerspoon/issues/2264676679/?project=5220516&query=is%3Aunresolved+release%3Alatest&statsPeriod=14d
• https://sentry.io/organizations/hammerspoon/issues/2263890376/?project=5220516&query=is%3Aunresolved+release%3Alatest&statsPeriod=14d
• https://sentry.io/organizations/hammerspoon/issues/2264076080/?project=5220516&query=is%3Aunresolved+release%3Alatest&statsPeriod=14d
• https://sentry.io/organizations/hammerspoon/issues/2263909041/?project=5220516&query=is%3Aunresolved+release%3Alatest&statsPeriod=14d
• https://sentry.io/organizations/hammerspoon/issues/2252842063/?project=5220516&query=is%3Aunresolved+release%3Alatest&statsPeriod=14d
• https://sentry.io/organizations/hammerspoon/issues/2262301597/?project=5220516&query=is%3Aunresolved+release%3Alatest&statsPeriod=14d
• https://sentry.io/organizations/hammerspoon/issues/2260433876/?project=5220516&query=is%3Aunresolved+release%3Alatest&statsPeriod=14d
• https://sentry.io/organizations/hammerspoon/issues/2254695465/?project=5220516&query=is%3Aunresolved+release%3Alatest&statsPeriod=14d

Here are some evidence points I have so far:

1. They all start with an OS callback that leads to us calling protectedCallAndTraceback. There are a couple of others that happen during the first load of init.lua, but we'll ignore those for now.
2. Generally speaking they are all something to do with pointers not being what Lua is expecting (either NULL or garbage), which strongly suggests (imo) that this is some kind of lifecycle issue - ie they're storing a reference to something that's been subsequently deallocated.
3. We don't get very many of these - in the week since 0.9.84 was released these particular crashes only number around 20, out of thousands of user sessions. Sentry doesn't break down a ton of detail here (in part because we deliberately don't enable active session tracking), but they report well over 99% of sessions are crash free. Still, it annoys me to know that these crashes all hint at some kind of lifecycle bug we haven't found yet.
4. Looking at the backtraces, they mostly fall into either hs.timer or hs.eventtap callbacks, but there are others, which suggests to me that it's not a specific bug in either of those modules, but rather a systemic flaw.
5. We have protections against (at least):
   • trying to call Lua off the main thread
   • lua_State having been replaced since the callback was set up, at least in hs.timer (via the relatively new checkLuaSkinInstance in 0.9.83)
   • Lua stack overgrowth via the _lua_stackguard macros
6. Looking at the breadcrumb logs from the crashes, it's not generally the case that the crash happens imminently after a LuaSkin reload
7. Because they all start from C, they call [LuaSkin sharedWithState:NULL] which guarantees them the main Lua State, they're not coming in on a co-routine state (this kind of crash report predates co-routines anyway AFAIK, but we don't have historical data to back that up). This would also be covered by the LuaSkin UUID check, at least in hs.timer.

So, it seems relatively safe to say that these aren't happening when Lua is being torn down, and their relative consistency makes me suspect they're not stack/heap corruption, although I can't rule that out. I have some hypotheses:

1. They are happening at some transition period between a co-routine lua_State and the main lua_State (I have no idea how this works under the hood, maybe it's not possible)
2. Somewhere we're running the Objective C event loop in one of our modules, causing it to advance and process incoming events while we're in the middle of a Lua->C situation and the Lua state gets confused
3. We just have one or more memory corruption bugs in some C code somewhere
4. We have a very subtle Lua API interaction bug
5. We're hitting genuine bugs in Lua (seems unlikely that they would persist for this long without other much fancier users of Lua, noticing)

My bet is on 2, 3 or 4, but I don't have any evidence to support that yet.

So....... thoughts? :)

[cmsj]

I'm genuinely considering investigating what it would take to ship a single release with all of the malloc/zombies/sanitiser debugging features enabled, just to see if the nature of these reports changes (ideally in a way that gives us more information to go on).

Edit: Turns out our release builds have partial ASAN enabled, Main Thread Checker, and Zombie Checker, enabled already.

[cmsj]

Since we're apparently already paying the (approx 2x) performance cost of the Address Sanitiser in release builds, #2760 enables some of the additional options. I think we should carry these all for a single release that lasts 1-2 weeks and see what, if any, difference it makes to the quantity/quality of the crash reports we get, then revert the change. Any objections?

[asmagill]

No objections; It will take me a little longer to go through the items above and the list of crashes to see if I have any immediate insights, but as to capturing more detail in crashlogs, I'm all for seeing if this helps.

[asmagill]

They are happening at some transition period between a co-routine lua_State and the main lua_State (I have no idea how this works under the hood, maybe it's not possible)

Coroutines that work with the Hammerspoon modules are a pretty new thing... and even so, I doubt more than a handful of our users are using them yet. And even coroutine lua code runs on the main thread, so until a coroutine yields, which is the proper lua way of transitioning out of a coroutine, a queued event callback can't run.

Somewhere we're running the Objective C event loop in one of our modules, causing it to advance and process incoming events while we're in the middle of a Lua->C situation and the Lua state gets confused

Unless they're using my hs._asm.extras module (which I don't hide, but I don't promote, either... it's usually where I try out oddball things to see if they are worth pursuing further in a more official place), I don't think so... unless it's a side effect of another Objective-C operation, but I'd expect that to be clearly noted in the API docs.

Once I got co-routines working, I abandoned my testing with advancing the main event loop -- it introduces too much uncertainty, in my opinion.

I'm in agreement that 3 or 4 seem most likely, though.

---

I've also noticed in some of my own debugging that occasionally if invalid data is passed into an Objective-C method, it might be as many as 10 levels deeper in the traceback before the actual crash -- for example passing in a NULL value to a method marked non-nullable -- it's not always the called method but something it calls (or that calls, or...) before the crash occurs. It might be worth biting the bullet and addressing all of the warnings generated when building Hammerspoon... I know most are already set to cause an error during build, but not all are.

Would it be worth renaming all of the internal.m files so that even in a minimalist crashlog it's more clear which specific module contains the crashing code? It'd be an annoying change requiring modifications to almost all module files, lua and Objective-C, but maybe its time to bite that bullet as well?

[cmsj]

Couple of random thoughts while doing the dishes:

• Lua does a lot of work before it calls a function, we essentially just call _pcall() - are we missing a trick there?
• If we wrap debug.traceback we could capture protectedCallAndTraceback tracebacks as breadcrumbs. Not sure that this would be useful, but an extra datapoint might reveal an error pattern preceding these crashes

[asmagill]

lua_pcall is supposed to do that work for us, including guaranteeing a return (rather than a long-jump) on error.

Wrapping debug.traceback would at least make it clear if the crash occurs before the callback invokes lua or after... if it's before (or during, though during would put at least one of the lua_?call functions on the stack) then there would be no breadcrumb. But does that potentially leak private info?

[cmsj]

potentially it does, yes, in the sense that we'd see function names and filenames

[cmsj]

So, I've checked through the codebase and there's only one place we call CFRunLoopRun() - for enumerating mice in hs.mouse and it looks like we're doing it properly (ie with a custom event loop, so it shouldn't be processing any other events).

I did notice that when we do CFRunLoopAddSource() we're not very consistent about which runloop we ask to run on - sometimes it's CFRunLoopGetMain() and sometimes it's CFRunLoopGetCurrent(). In most cases those are probably the same, since GetCurrent() returns the runloop for the current thread, but we might want to review these just to make sure.

[cmsj]

Similarly we have some inconsistencies between adding source with either kCFRunLoopDefaultMode or kCFRunLoopCommonModes

[asmagill]

regarding the modes, I vaguely remember uncovering an issue with the mode used for timers when I was working on a menubar replacement (development on it stalled, because we fixed some errors in ours, but I eventually want to get back to it)... my replacement allowed for changes to the menu while it was open but timer's didn't fire while the menu was showing -- eventtaps did, though, which is why I looked at the modes and noticed the difference. I'll try to dig up the specific issue number when I get back home tonight, but if I recall my finding correctly, there were no issues when I changed the timer modes during my initial tests...

A long winded way of agreeing we should standardized, but I think we want to standardize on what eventtap uses in this case -- I'll confirm tonight.

[latenitefilms]

Food for thought... as CommandPost has a consistent Lua codebase (as in, very few, if any users modify the Lua code), it might be worth having a look at the CommandPost Sentry to see if there's any similar crashes between CommandPost and Hammerspoon?

CommandPost is pretty much always in-sync with the master Hammerspoon branch too, with the note that I generally update pods more regularly in CommandPost.

[cmsj]

@latenitefilms interestingly, you don't seem to have the same sorts of crashes in CommandPost

[cmsj]

I'm going to put out a release now, to get these updated sanitiser/assert things in the wild, and we can see what reports come in over the next week (assuming it doesn't all explode immediately!)

[latenitefilms]

@latenitefilms interestingly, you don't seem to have the same sorts of crashes in CommandPost

Well, that is... odd, given it's the same codebase, and I'm almost using every Hammerspoon extension.

[cmsj]

I take it as a positive sign - it likely means that people are using our API in ways we didn't think of and are triggering weirdness.

The challenge now, is to figure out what it is. If one/several of them would file GH issues, this would go a lot quicker, I suspect!