Hammerspoon: Crash - Skin.m line 406 - -[LuaSkin checkArgs:]

[latenitefilms]

See: http://crashes.to/s/f477e2cc3d9

Code in question: [_skin pushNSObject:stdOutArg];

Logs:

1443 | \| | 08:00:43:467 (UTC) | \| | hs.task terminationHandler block encountered an exception: *** -[NSConcreteFileHandle readDataOfLength:]: Resource temporarily unavailable
-- | -- | -- | -- | --
1444 | \| | 08:00:43:467 (UTC) | \| | (WARNING) hs.task terminationHandler block encountered an exception: *** -[NSConcreteFileHandle readDataOfLength:]: Resource temporarily unavailable
1445 | \| | 08:00:43:470 (UTC) | \| | hs.task terminationHandler block encountered an exception: *** -[NSConcreteFileHandle readDataOfLength:]: Resource temporarily unavailable
1446 | \| | 08:00:43:470 (UTC) | \| | (WARNING) hs.task terminationHandler block encountered an exception: *** -[NSConcreteFileHandle readDataOfLength:]: Resource temporarily unavailable

[latenitefilms]

Maybe related?

https://stackoverflow.com/questions/7871061/how-to-use-nsfilehandles-writeabilityhandler

[cmsj]

I disagree with your "Code in question" - if you look at "Keys" section in "View all Sessions" on the crash report, there's:

Assertion failed: (ref != LUA_NOREF && ref != LUA_REFNIL), function -[LuaSkin pushLuaRef:ref:], file /Users/chrishocking/Github/CommandPost-App/LuaSkin/LuaSkin/Skin.m, line 389.

which is more likely to be one of the two lines preceding the pushNSObject. It's unlikely to be the userData->luaStreamCallback ref push, since that was validated on line 908, which leaves userData->selfRef. My reading of the code is that this can only be LUA_NOREF or LUA_REFNIL in three situations:

1. The task object hasn't been created yet
2. The task object has been GC'd
3. The task object's terminationHandler has been called

It seems impossible that 1. could be relevant here. So, that leaves the question of whether the file handles can call the observer block (as defined between lines 891 and 958, after the Task has either terminated on its own, or because we GC'd it.

Our terminationHandler explicitly closes the stdout and stderr file handles, which rather suggests that there won't be any more calls to the observer block.

That just leaves the GC path, and looking at task_gc I note that it makes terminationHandler a blank block before calling [task terminate] and then unreffing userData->selfRef so I'm wondering if this is the cause of the issue, but this is all unsubstantiated.

[latenitefilms]

Ha! Sorry, I didn't notice the Keys section. That's my laptop - but I don't remember CommandPost crashing today - strange!

[latenitefilms]

Also see: #1860

[latenitefilms]

@cmsj - Will leave you to close this issue if you think it's not useful.

[latenitefilms]

Fixed in #1938

[joemiller]

I am running into an issue that I think might be related.

This simple test case from https://github.com/Hammerspoon/hammerspoon/pull/1938#issuecomment-420971406 works OK:

> task = hs.task.new("/bin/ls", function(exitCode, stdOut, stdErr)
    print(string.format("exitCode: %s", exitCode))
    print(string.format("stdOut: %s", stdOut))
    print(string.format("stdErr: %s", stdErr))      
end, function(exitCode, stdOut, stdErr)
    print(string.format("exitCode: %s", exitCode))
    print(string.format("stdOut: %s", stdOut))
    print(string.format("stdErr: %s", stdErr))      
    return true
end):start()

2019-08-16 13:59:02: stream exitCode: hs.task: /bin/ls  (0x7fe07b308338)
2019-08-16 13:59:02: stream stdOut: README.md
Spoons
anycomplete.lua
app_jump_menu.lua
app_watcher.lua
foo
hammerspoon-modal-menu-example.png
init.lua
notification_center.lua
utils.lua
volumes.lua
wifi_watcher.lua
window_controls.lua
wireguard-reconnect.sh

2019-08-16 13:59:02: stream stdErr: 
2019-08-16 13:59:02: exitCode: 0
2019-08-16 13:59:02: stdOut: 
2019-08-16 13:59:02: stdErr: 

The next test case usually (but not always) fails. Unlike the simpler /bin/ls example above which runs to completion quickly and only makes one call to the streaming callback, this example executes a script which takes ~4-5 seconds to run and triggers multiple callbacks.

/tmp/foo.sh:

#!/bin/bash

set -x

echo hello args $@
sleep 2
echo i am still here $RANDOM
sleep 2
echo ok i am done now $RANDOM
#ls -lR
#exit 1
exit 0

> task = hs.task.new("/tmp/foo.sh", function(exitCode, stdOut, stdErr)
    print(string.format("exitCode: %s", exitCode))
    print(string.format("stdOut: %s", stdOut))
    print(string.format("stdErr: %s", stdErr))      
end, function(exitCode, stdOut, stdErr)
    print(string.format("stream exitCode: %s", exitCode))
    print(string.format("stream stdOut: %s", stdOut))
    print(string.format("stream stdErr: %s", stdErr))       
    return true
end):start()

The crash message from hammerspoon when this code fails is:

2019-08-16 14:01:19.396 Hammerspoon[59188:15192976] *** Assertion failure in -[LuaSkin pushLuaRef:ref:], /Users/cmsj/hacking/hammerspoon/hammerspoon/LuaSkin/LuaSkin/Skin.m:386

[1]  + 59188 illegal hardware instruction  /Applications/Hammerspoon.app/Contents/MacOS/Hammerspoon

[cmsj]

@joemiller THANK YOU! This seems to be a reliable reproducer for one of our most common crash reports, that has eluded a reproducer so far. I can't begin to describe how valuable it is to have people report crashing configs!

@asmagill I'm going to be away from my main Mac for a couple of weeks, and for some reason I can't get either Xcode 10 or 11 to debug properly on my Catalina beta macbook. Are you able to get a successful debug session with either current master or the 0.9.75 tag? If so, would you be interested in looking at this crash? If not, it'll be the first thing I look at when I'm home from travelling :)

[asmagill]

I won't have a chance to try any fixes until tonight or tomorrow, but after reviewing the code...

I'm not nearly as familiar with NSTask as I'd like to be, but is it possible for the stream observer for the NSFileHandleReadCompletionNotification notification to be invoked after the NSTask object has officially signaled that the task has terminated? If so, then the selfRef for the userdata will have been cleared in the termination handler (Line 163) but is never checked for validity in the stream's block (Line 930).

Under this assumption, which I admit I'm currently making with no evidence beyond the fact that I can't envision any other way that selfRef could be NOREF or NILREF where the crash occurs (it can't be because of luaStreamCallback because of line 909), the question becomes should this last invocation of the stream callback include the userdata as one of its arguments or should it be nil which we could document indicates that this is the "last" invocation to expect? I'm leaning towards the later because we're guaranteed that the termination handler will be invoked and is the "correct" place to clean up after ourselves (releasing the selfRef)... for the former, we'd have to set a flag when isStream is true rather then release selfRef in the termination handler so that the stream callback knows to clear it instead and ONLY works if the stream handler is ALWAYS called once more after the termination handler, otherwise we've got an extra reference to the userdata which would prevent its release during garbage collection.

Unless we want to set different flags in both handlers and then setup a timer which checks that both flags are set before clearing selfRef... which just sounds awful kludgey and adds another annoying thing to track to ensure it gets cleared during a full garbage collection during reload...