Hammerspoon Crashes on Reload

[latenitefilms]

@cmsj & @asmagill - Since updating CommandPost to the latest Hammerspoon code, CommandPost now crashes whenever you try to reload. I can also reproduce this by building Hammerspoon from the latest master branch - so it seems one of the most recent commits has broken something?

 # Crashlytics - plaintext stacktrace downloaded by Chris Hocking at Mon, 05 Feb 2018 02:59:49 GMT
# URL: https://fabric.io/latenite-films/mac/apps/org.latenitefilms.commandpost/issues/5a765ed38cb3c2fa633fa597?time=last-hour/sessions/604aca31fb98467796b8a96d11a6767a_DNE_0_v2
# Organization: LateNite Films
# Platform: mac_os_x
# Application: CommandPost
# Version: 1.0.0-beta.22
# Bundle Identifier: org.latenitefilms.CommandPost
# Issue #: 78
# Issue ID: 5a765ed38cb3c2fa633fa597
# Session ID: 604aca31fb98467796b8a96d11a6767a_DNE_0_v2
# Date: 2018-02-05T02:56:00Z
# OS Version: 10.13.2 (17C88)
# Device: MacBook Pro 14,3
# RAM Free: 1.4%
# Disk Free: 5%

#0. Crashed: com.apple.main-thread
0  LuaSkin                        0x105f5e0ae lua_atpanic (lapi.c:137)
1  CommandPost                    0x105c1b568 MJLuaAlloc (MJLua.m:587)
2  CommandPost                    0x105c1bec0 MJLuaReplace (MJLua.m:568)
3  libdispatch.dylib              0x7fff5b47e591 _dispatch_call_block_and_release + 12
4  libdispatch.dylib              0x7fff5b476d50 _dispatch_client_callout + 8
5  libdispatch.dylib              0x7fff5b48232d _dispatch_main_queue_callback_4CF + 1148
6  CoreFoundation                 0x7fff33c9a7a9 __CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ + 9
7  CoreFoundation                 0x7fff33c5c9ca __CFRunLoopRun + 2586
8  CoreFoundation                 0x7fff33c5bd23 CFRunLoopRunSpecific + 483
9  HIToolbox                      0x7fff32f73e26 RunCurrentEventLoopInMode + 286
10 HIToolbox                      0x7fff32f73b96 ReceiveNextEventCommon + 613
11 HIToolbox                      0x7fff32f73914 _BlockUntilNextEventMatchingListInModeWithFilter + 64
12 AppKit                         0x7fff3123ef5f _DPSNextEvent + 2085
13 AppKit                         0x7fff319d4b4c -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 3044
14 AppKit                         0x7fff31233d6d -[NSApplication run] + 764
15 AppKit                         0x7fff31202f1a NSApplicationMain + 804
16 libdyld.dylib                  0x7fff5b4b0115 start + 1

--

#0. Crashed: com.apple.main-thread
0  LuaSkin                        0x105f5e0ae lua_atpanic (lapi.c:137)
1  CommandPost                    0x105c1b568 MJLuaAlloc (MJLua.m:587)
2  CommandPost                    0x105c1bec0 MJLuaReplace (MJLua.m:568)
3  libdispatch.dylib              0x7fff5b47e591 _dispatch_call_block_and_release + 12
4  libdispatch.dylib              0x7fff5b476d50 _dispatch_client_callout + 8
5  libdispatch.dylib              0x7fff5b48232d _dispatch_main_queue_callback_4CF + 1148
6  CoreFoundation                 0x7fff33c9a7a9 __CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ + 9
7  CoreFoundation                 0x7fff33c5c9ca __CFRunLoopRun + 2586
8  CoreFoundation                 0x7fff33c5bd23 CFRunLoopRunSpecific + 483
9  HIToolbox                      0x7fff32f73e26 RunCurrentEventLoopInMode + 286
10 HIToolbox                      0x7fff32f73b96 ReceiveNextEventCommon + 613
11 HIToolbox                      0x7fff32f73914 _BlockUntilNextEventMatchingListInModeWithFilter + 64
12 AppKit                         0x7fff3123ef5f _DPSNextEvent + 2085
13 AppKit                         0x7fff319d4b4c -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 3044
14 AppKit                         0x7fff31233d6d -[NSApplication run] + 764
15 AppKit                         0x7fff31202f1a NSApplicationMain + 804
16 libdyld.dylib                  0x7fff5b4b0115 start + 1

#1. Thread
0  libsystem_kernel.dylib         0x7fff5b600562 __workq_kernreturn + 10
1  libsystem_pthread.dylib        0x7fff5b73b06a _pthread_wqthread + 1035
2  libsystem_pthread.dylib        0x7fff5b73ac4d start_wqthread + 13
3  (Missing)                      0x0 (Missing)

#2. Thread
0  libsystem_kernel.dylib         0x7fff5b600562 __workq_kernreturn + 10
1  libsystem_pthread.dylib        0x7fff5b73b06a _pthread_wqthread + 1035
2  libsystem_pthread.dylib        0x7fff5b73ac4d start_wqthread + 13
3  (Missing)                      0x120080001200 (Missing)

#3. com.twitter.crashlytics.mac.MachExceptionServer
0  CommandPost                    0x105ccc341 CLSProcessRecordAllThreads + 1449
1  CommandPost                    0x105ccc1de CLSProcessRecordAllThreads + 1094
2  CommandPost                    0x105cbbad1 CLSHandler + 45
3  CommandPost                    0x105cb6bc5 CLSMachExceptionServer + 546
4  libsystem_pthread.dylib        0x7fff5b73b6c1 _pthread_body + 340
5  libsystem_pthread.dylib        0x7fff5b73b56d _pthread_start + 375
6  libsystem_pthread.dylib        0x7fff5b73ac5d thread_start + 13

#4. Thread
0  libsystem_kernel.dylib         0x7fff5b5f67c2 mach_msg_trap + 10
1  libsystem_kernel.dylib         0x7fff5b5f5cdc mach_msg + 60
2  CoreMIDI                       0x7fff349f1b83 XServerMachPort::ReceiveMessage(int&, void*, int&) + 93
3  CoreMIDI                       0x7fff34a089a0 MIDIProcess::RunMIDIInThread() + 336
4  CoreMIDI                       0x7fff34a19c8e XThread::RunHelper(void*) + 10
5  CoreMIDI                       0x7fff34a1de7b CAPThread::Entry(CAPThread*) + 77
6  libsystem_pthread.dylib        0x7fff5b73b6c1 _pthread_body + 340
7  libsystem_pthread.dylib        0x7fff5b73b56d _pthread_start + 375
8  libsystem_pthread.dylib        0x7fff5b73ac5d thread_start + 13

#5. com.apple.NSURLConnectionLoader
0  libsystem_kernel.dylib         0x7fff5b5f67c2 mach_msg_trap + 10
1  libsystem_kernel.dylib         0x7fff5b5f5cdc mach_msg + 60
2  CoreFoundation                 0x7fff33c5d355 __CFRunLoopServiceMachPort + 341
3  CoreFoundation                 0x7fff33c5c6a7 __CFRunLoopRun + 1783
4  CoreFoundation                 0x7fff33c5bd23 CFRunLoopRunSpecific + 483
5  CFNetwork                      0x7fff32dd4f84 -[__CoreSchedulingSetRunnable runForever] + 722
6  Foundation                     0x7fff35d49e48 __NSThread__start__ + 1197
7  libsystem_pthread.dylib        0x7fff5b73b6c1 _pthread_body + 340
8  libsystem_pthread.dylib        0x7fff5b73b56d _pthread_start + 375
9  libsystem_pthread.dylib        0x7fff5b73ac5d thread_start + 13

#6. Thread
0  libsystem_kernel.dylib         0x7fff5b600562 __workq_kernreturn + 10
1  libsystem_pthread.dylib        0x7fff5b73b26f _pthread_wqthread + 1552
2  libsystem_pthread.dylib        0x7fff5b73ac4d start_wqthread + 13

#7. Thread
0  libsystem_kernel.dylib         0x7fff5b600562 __workq_kernreturn + 10
1  libsystem_pthread.dylib        0x7fff5b73b06a _pthread_wqthread + 1035
2  libsystem_pthread.dylib        0x7fff5b73ac4d start_wqthread + 13
3  (Missing)                      0x630069006c0070 (Missing)

#8. Thread
0  libsystem_kernel.dylib         0x7fff5b600562 __workq_kernreturn + 10
1  libsystem_pthread.dylib        0x7fff5b73b06a _pthread_wqthread + 1035
2  libsystem_pthread.dylib        0x7fff5b73ac4d start_wqthread + 13
3  (Missing)                      0x6080000e4201 (Missing)

#9. Thread
0  libsystem_kernel.dylib         0x7fff5b600562 __workq_kernreturn + 10
1  libsystem_pthread.dylib        0x7fff5b73b26f _pthread_wqthread + 1552
2  libsystem_pthread.dylib        0x7fff5b73ac4d start_wqthread + 13

#10. Thread
0  libsystem_kernel.dylib         0x7fff5b600562 __workq_kernreturn + 10
1  libsystem_pthread.dylib        0x7fff5b73b06a _pthread_wqthread + 1035
2  libsystem_pthread.dylib        0x7fff5b73ac4d start_wqthread + 13
3  (Missing)                      0x100dfe9f0 (Missing)

#11. com.apple.NSEventThread
0  libsystem_kernel.dylib         0x7fff5b5f67c2 mach_msg_trap + 10
1  libsystem_kernel.dylib         0x7fff5b5f5cdc mach_msg + 60
2  CoreFoundation                 0x7fff33c5d355 __CFRunLoopServiceMachPort + 341
3  CoreFoundation                 0x7fff33c5c6a7 __CFRunLoopRun + 1783
4  CoreFoundation                 0x7fff33c5bd23 CFRunLoopRunSpecific + 483
5  AppKit                         0x7fff3137c3c8 _NSEventThread + 184
6  libsystem_pthread.dylib        0x7fff5b73b6c1 _pthread_body + 340
7  libsystem_pthread.dylib        0x7fff5b73b56d _pthread_start + 375
8  libsystem_pthread.dylib        0x7fff5b73ac5d thread_start + 13

[asmagill]

Confirmed.

Crashed Thread:        0  Dispatch queue: com.apple.main-thread

Exception Type:        EXC_BAD_ACCESS (SIGABRT)
Exception Codes:       KERN_INVALID_ADDRESS at 0x0000000000000018
Exception Note:        EXC_CORPSE_NOTIFY

VM Regions Near 0x18:
--> 
    __TEXT                 000000010d695000-000000010db5a000 [ 4884K] r-x/rwx SM=COW  /Applications/Developer/Hammerspoon.app/Contents/MacOS/Hammerspoon

Application Specific Information:
/opt/amagill/src/hammerspoon/hammerspoon/LuaSkin/lua-5.3.4/src/lapi.c:137:9: runtime error: member access within null pointer of type 'lua_State' (aka 'struct lua_State')
SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior /opt/amagill/src/hammerspoon/hammerspoon/LuaSkin/lua-5.3.4/src/lapi.c:137:9 in 
=================================================================
==7857==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000018 (pc 0x00010de77ef6 bp 0x7ffee2569d70 sp 0x7ffee2569d10 T0)
==7857==The signal is caused by a READ memory access.
==7857==Hint: address points to the zero page.
    #0 0x10de77ef5 in lua_atpanic lapi.c:137
    #1 0x10d6af072 in MJLuaAlloc MJLua.m:587
    #2 0x10d6b0a89 in MJLuaReplace MJLua.m:567
    #3 0x10d69f86e in -[MJAppDelegate reloadConfig:] MJAppDelegate.m:296
    #4 0x7fff2ce56515 in -[NSApplication(NSResponder) sendAction:to:from:] (AppKit:x86_64+0x7da515)
    #5 0x7fff2c8ead46 in -[NSMenuItem _corePerformAction] (AppKit:x86_64+0x26ed46)
    #6 0x7fff2c8eaace in -[NSCarbonMenuImpl performActionWithHighlightingForItemAtIndex:] (AppKit:x86_64+0x26eace)
    #7 0x7fff2c8e9932 in -[NSMenu performKeyEquivalent:] (AppKit:x86_64+0x26d932)
    #8 0x7fff2ce5517c in routeKeyEquivalent (AppKit:x86_64+0x7d917c)
    #9 0x7fff2ce526b0 in -[NSApplication(NSEvent) sendEvent:] (AppKit:x86_64+0x7d66b0)
    #10 0x7fff2c6b34ec in -[NSApplication run] (AppKit:x86_64+0x374ec)
    #11 0x7fff2c682669 in NSApplicationMain (AppKit:x86_64+0x6669)
    #12 0x10d6a1ed1 in main MJAppDelegate.m:374
    #13 0x7fff57634014 in start (libdyld.dylib:x86_64+0x1014)
 
==7857==Register values:
rax = 0x0000000000000018  rbx = 0x00007ffee2569dc0  rcx = 0x0000100000000003  rdx = 0x0000000000000000  
rdi = 0x0000000000000000  rsi = 0x0000000000000001  rbp = 0x00007ffee2569d70  rsp = 0x00007ffee2569d10  
 r8 = 0x000000000000003f   r9 = 0x0000000000000005  r10 = 0x00007fff57784722  r11 = 0x0000000000000206  
r12 = 0x000060400003fa10  r13 = 0x00007fff56a0be80  r14 = 0x000060800001a820  r15 = 0x000000010daf44ee  
AddressSanitizer can not provide additional info.
SUMMARY: AddressSanitizer: SEGV lapi.c:137 in lua_atpanic
==7857==ABORTING
 
Performing @selector(reloadConfig:) from sender NSMenuItem 0x60800001a820
abort() called

Thread 0 Crashed:: Dispatch queue: com.apple.main-thread
0   libsystem_kernel.dylib        	0x00007fff57784afe __pthread_kill + 10
1   libsystem_pthread.dylib       	0x00007fff57943150 pthread_kill + 333
2   libsystem_c.dylib             	0x00007fff576e01ae abort + 127
3   libclang_rt.asan_osx_dynamic.dylib	0x000000010e060e96 __sanitizer::Abort() + 70
4   libclang_rt.asan_osx_dynamic.dylib	0x000000010e05c188 __sanitizer::Die() + 120
5   libclang_rt.asan_osx_dynamic.dylib	0x000000010e0426d1 __asan::ScopedInErrorReport::~ScopedInErrorReport() + 321
6   libclang_rt.asan_osx_dynamic.dylib	0x000000010e0413d2 __asan::ReportDeadlySignal(int, __sanitizer::SignalContext const&) + 162
7   libclang_rt.asan_osx_dynamic.dylib	0x000000010e040b3d __asan::AsanOnDeadlySignal(int, void*, void*) + 157
8   libsystem_platform.dylib      	0x00007fff57936f5a _sigtramp + 26
9   ???                           	000000000000000000 0 + 0
10  org.hammerspoon.Hammerspoon   	0x000000010d6af073 MJLuaAlloc + 867 (MJLua.m:587)
11  org.hammerspoon.Hammerspoon   	0x000000010d6b0a8a MJLuaReplace + 186 (MJLua.m:568)
12  org.hammerspoon.Hammerspoon   	0x000000010d69f86f -[MJAppDelegate reloadConfig:] + 287 (MJAppDelegate.m:296)
13  com.apple.AppKit              	0x00007fff2ce56516 -[NSApplication(NSResponder) sendAction:to:from:] + 312
14  com.apple.AppKit              	0x00007fff2c8ead47 -[NSMenuItem _corePerformAction] + 323
15  com.apple.AppKit              	0x00007fff2c8eaacf -[NSCarbonMenuImpl performActionWithHighlightingForItemAtIndex:] + 114
16  com.apple.AppKit              	0x00007fff2c8e9933 -[NSMenu performKeyEquivalent:] + 363
17  com.apple.AppKit              	0x00007fff2ce5517d routeKeyEquivalent + 884
18  com.apple.AppKit              	0x00007fff2ce526b1 -[NSApplication(NSEvent) sendEvent:] + 1041
19  com.apple.AppKit              	0x00007fff2c6b34ed -[NSApplication run] + 812
20  com.apple.AppKit              	0x00007fff2c68266a NSApplicationMain + 804
21  org.hammerspoon.Hammerspoon   	0x000000010d6a1ed2 main + 34 (MJAppDelegate.m:374)
22  libdyld.dylib                 	0x00007fff57634015 start + 1

Looks like something got moved so that the reassignment of the panic handler is getting triggered before the new state is assigned to the skin... a quick glance suggests that this should be failing every time, not just on a reload, so... I guess its going to take more then a quick glance.

I'll see if I can figure it out, unless @cmsj chimes in sooner.

[asmagill]

@cmsj, because of the way LuaSkin is allocated and deallocated, createLuaState is only invoked from within the the dispatch_once clause of sharedWithDelegate:.

The previous solution was to include the following lines in MJLua.m in the MJLuaAlloc function after calling the shared method for the "first" time this go around:

    if (!skin.L) {
        [skin createLuaState];
    }

This fix has worked for me, so I'm sticking it back in for now; a better long term solution would be to have an explicit "reload" method within LuaSkin itself that manages things so MJReplace can invoke it rather then the current process.

[latenitefilms]

@asmagill - Legend, thank you!! I can confirm the fix works!

However, for what it's worth - reloads now seem far slower than they used to be?

[asmagill]

If you're using a debug build (see #1671) I'm not surprised -- some stuff has been turned on to help track down memory leaks and hopefully provide more details about some of the more obscure crashes.

For now, you'll need to either use the release scheme or manually adjust Hammerspoon.xcscheme (see b5efc29)

[latenitefilms]

@asmagill - Ummm... I am using the release build - this is the script I'm using:

https://github.com/CommandPost/CommandPost/blob/develop/scripts/build_commandpost_release.sh

[asmagill]

Then I'm not sure. The LuaSkin log delegate is set a lot sooner, so it may be logging a lot more through hs.luaSkinLog during a start up.

Would need to know specifically what is being slower and whether it was part of the tear-down or build-up portion of the reload.

[cmsj]

ugh, sorry guys, that was a stupid thing to delete!

[latenitefilms]

@asmagill When I press the "Reload" button on the Console it takes about 4-6 seconds before the customised Touch Bar disappears, and the Console contents clears - so I guess the tear-down is taking a longer than expected time to do its thing?

However, I just fired up an older build, using the same Lua code - and it's only JUST faster. It takes about 3-4 seconds to reload. Interesting, each time I reload it always takes a slightly different amount of time.

[cmsj]

Might be worth profiling HS with Xcode's Instruments and looking for hot spots while reloading?