Hammerspoon / hammerspoon

Staggeringly powerful macOS desktop automation with Lua
http://www.hammerspoon.org
MIT License
11.99k stars 582 forks source link

Crash - MJConsoleWindowController.m line 132 #1651

Closed latenitefilms closed 6 years ago

latenitefilms commented 6 years ago

FYI:

# Application: CommandPost
# Version: 1.0.0-beta.20
# Bundle Identifier: org.latenitefilms.CommandPost
# Issue #: 68
# Issue ID: 5a5dc8238cb3c2fa63eec308
# Session ID: b4af53a395114d31afb8419a1ba85f40_0b10d31cfaa111e7a2ec56847afe9799_0_v2
# Date: 2018-01-15T14:04:00Z
# OS Version: 10.12.6 (16G1114)
# Device: iMac 11,1
# RAM Free: < 1%
# Disk Free: 4.6%

#0. Crashed: com.apple.main-thread
0  libsystem_kernel.dylib         0x7fffb518ad42 __pthread_kill + 10
1  libsystem_pthread.dylib        0x7fffb5278457 pthread_kill + 90
2  libsystem_c.dylib              0x7fffb50f0420 abort + 129
3  libsystem_malloc.dylib         0x7fffb51eaf5d szone_error + 626
4  libsystem_malloc.dylib         0x7fffb51ec925 small_free_list_remove_ptr_no_clear + 766
5  libsystem_malloc.dylib         0x7fffb51e0823 small_malloc_from_free_list + 159
6  libsystem_malloc.dylib         0x7fffb51de953 szone_malloc_should_clear + 1649
7  libsystem_malloc.dylib         0x7fffb51de282 malloc_zone_malloc + 107
8  libsystem_malloc.dylib         0x7fffb51dd200 malloc + 24
9  libicucore.A.dylib             0x7fffb41d5aeb icu::DecimalFormat::operator=(icu::DecimalFormat const&) + 83
10 libicucore.A.dylib             0x7fffb41d58c3 icu::DecimalFormat::clone() const + 133
11 libicucore.A.dylib             0x7fffb4329e23 icu::SimpleDateFormat::getLevelFromChar(unsigned short) + 95
12 libicucore.A.dylib             0x7fffb4328120 icu::SimpleDateFormat::subFormat(icu::UnicodeString&, unsigned short, int, UDisplayContext, int, icu::FieldPositionHandler&, icu::Calendar&, icu::SimpleDateFormatMutableNFs&, UErrorCode&) const + 438
13 libicucore.A.dylib             0x7fffb41e712c icu::SimpleDateFormat::_format(icu::Calendar&, icu::UnicodeString&, icu::FieldPositionHandler&, UErrorCode&) const + 540
14 libicucore.A.dylib             0x7fffb41e6ef5 icu::SimpleDateFormat::format(icu::Calendar&, icu::UnicodeString&, icu::FieldPosition&) const + 67
15 libicucore.A.dylib             0x7fffb41e6e95 icu::DateFormat::format(double, icu::UnicodeString&, icu::FieldPosition&) const + 107
16 libicucore.A.dylib             0x7fffb41e6dd7 udat_format + 269
17 CoreFoundation                 0x7fff9f36faa1 __cficu_udat_format + 49
18 CoreFoundation                 0x7fff9f36f94e CFDateFormatterCreateStringWithAbsoluteTime + 174
19 Foundation                     0x7fffa0d45e84 -[NSDateFormatter stringForObjectValue:] + 339
20 CommandPost                    0x1062cf28a -[MJConsoleWindowController appendString:type:] (MJConsoleWindowController.m:132)
21 CommandPost                    0x1062cec81 __34-[MJConsoleWindowController setup]_block_invoke (MJConsoleWindowController.m:72)
22 CommandPost                    0x1062d295d core_logmessage (MJLua.m:542)
23 LuaSkin                        0x106687920 luaD_precall (ldo.c:454)
24 LuaSkin                        0x106685e45 luaV_execute (lvm.c:1134)
25 LuaSkin                        0x106687a76 luaD_call (ldo.c:517)
26 LuaSkin                        0x106687ab7 luaD_callnoyield (ldo.c:527)
27 LuaSkin                        0x10668f6bb luai_objcttry (lobjectivec_exceptions.m:173)
28 LuaSkin                        0x106687f85 luaD_pcall (ldo.c:162)
29 LuaSkin                        0x106698588 lua_pcallk (lapi.c:968)
30 LuaSkin                        0x10667c713 -[LuaSkin protectedCallAndTraceback:nresults:] (Skin.m:227)
31 internal.so                    0x10c5dec3e event_callback (internal.m:73)
32 FSEvents                       0x7fffa04d5af3 implementation_callback_rpc + 1883
33 FSEvents                       0x7fffa04d36fe _Xcallback_rpc + 254
34 FSEvents                       0x7fffa04d37bc FSEventsD2F_server + 55
35 FSEvents                       0x7fffa04d8fdd FSEventsClientProcessMessageCallback + 44
36 CoreFoundation                 0x7fff9f31c39d __CFMachPortPerform + 253
37 CoreFoundation                 0x7fff9f31c289 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE1_PERFORM_FUNCTION__ + 41
38 CoreFoundation                 0x7fff9f31c201 __CFRunLoopDoSource1 + 465
39 CoreFoundation                 0x7fff9f314105 __CFRunLoopRun + 2405
40 CoreFoundation                 0x7fff9f313544 CFRunLoopRunSpecific + 420
41 HIToolbox                      0x7fff9e872ebc RunCurrentEventLoopInMode + 240
42 HIToolbox                      0x7fff9e872cf1 ReceiveNextEventCommon + 432
43 HIToolbox                      0x7fff9e872b26 _BlockUntilNextEventMatchingListInModeWithFilter + 71
44 AppKit                         0x7fff9ce09a54 _DPSNextEvent + 1120
45 AppKit                         0x7fff9d5857ee -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 2796
46 AppKit                         0x7fff9cdfe3db -[NSApplication run] + 926
47 AppKit                         0x7fff9cdc8e0e NSApplicationMain + 1237
48 libdyld.dylib                  0x7fffb505c235 start + 1

--

#0. Crashed: com.apple.main-thread
0  libsystem_kernel.dylib         0x7fffb518ad42 __pthread_kill + 10
1  libsystem_pthread.dylib        0x7fffb5278457 pthread_kill + 90
2  libsystem_c.dylib              0x7fffb50f0420 abort + 129
3  libsystem_malloc.dylib         0x7fffb51eaf5d szone_error + 626
4  libsystem_malloc.dylib         0x7fffb51ec925 small_free_list_remove_ptr_no_clear + 766
5  libsystem_malloc.dylib         0x7fffb51e0823 small_malloc_from_free_list + 159
6  libsystem_malloc.dylib         0x7fffb51de953 szone_malloc_should_clear + 1649
7  libsystem_malloc.dylib         0x7fffb51de282 malloc_zone_malloc + 107
8  libsystem_malloc.dylib         0x7fffb51dd200 malloc + 24
9  libicucore.A.dylib             0x7fffb41d5aeb icu::DecimalFormat::operator=(icu::DecimalFormat const&) + 83
10 libicucore.A.dylib             0x7fffb41d58c3 icu::DecimalFormat::clone() const + 133
11 libicucore.A.dylib             0x7fffb4329e23 icu::SimpleDateFormat::getLevelFromChar(unsigned short) + 95
12 libicucore.A.dylib             0x7fffb4328120 icu::SimpleDateFormat::subFormat(icu::UnicodeString&, unsigned short, int, UDisplayContext, int, icu::FieldPositionHandler&, icu::Calendar&, icu::SimpleDateFormatMutableNFs&, UErrorCode&) const + 438
13 libicucore.A.dylib             0x7fffb41e712c icu::SimpleDateFormat::_format(icu::Calendar&, icu::UnicodeString&, icu::FieldPositionHandler&, UErrorCode&) const + 540
14 libicucore.A.dylib             0x7fffb41e6ef5 icu::SimpleDateFormat::format(icu::Calendar&, icu::UnicodeString&, icu::FieldPosition&) const + 67
15 libicucore.A.dylib             0x7fffb41e6e95 icu::DateFormat::format(double, icu::UnicodeString&, icu::FieldPosition&) const + 107
16 libicucore.A.dylib             0x7fffb41e6dd7 udat_format + 269
17 CoreFoundation                 0x7fff9f36faa1 __cficu_udat_format + 49
18 CoreFoundation                 0x7fff9f36f94e CFDateFormatterCreateStringWithAbsoluteTime + 174
19 Foundation                     0x7fffa0d45e84 -[NSDateFormatter stringForObjectValue:] + 339
20 CommandPost                    0x1062cf28a -[MJConsoleWindowController appendString:type:] (MJConsoleWindowController.m:132)
21 CommandPost                    0x1062cec81 __34-[MJConsoleWindowController setup]_block_invoke (MJConsoleWindowController.m:72)
22 CommandPost                    0x1062d295d core_logmessage (MJLua.m:542)
23 LuaSkin                        0x106687920 luaD_precall (ldo.c:454)
24 LuaSkin                        0x106685e45 luaV_execute (lvm.c:1134)
25 LuaSkin                        0x106687a76 luaD_call (ldo.c:517)
26 LuaSkin                        0x106687ab7 luaD_callnoyield (ldo.c:527)
27 LuaSkin                        0x10668f6bb luai_objcttry (lobjectivec_exceptions.m:173)
28 LuaSkin                        0x106687f85 luaD_pcall (ldo.c:162)
29 LuaSkin                        0x106698588 lua_pcallk (lapi.c:968)
30 LuaSkin                        0x10667c713 -[LuaSkin protectedCallAndTraceback:nresults:] (Skin.m:227)
31 internal.so                    0x10c5dec3e event_callback (internal.m:73)
32 FSEvents                       0x7fffa04d5af3 implementation_callback_rpc + 1883
33 FSEvents                       0x7fffa04d36fe _Xcallback_rpc + 254
34 FSEvents                       0x7fffa04d37bc FSEventsD2F_server + 55
35 FSEvents                       0x7fffa04d8fdd FSEventsClientProcessMessageCallback + 44
36 CoreFoundation                 0x7fff9f31c39d __CFMachPortPerform + 253
37 CoreFoundation                 0x7fff9f31c289 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE1_PERFORM_FUNCTION__ + 41
38 CoreFoundation                 0x7fff9f31c201 __CFRunLoopDoSource1 + 465
39 CoreFoundation                 0x7fff9f314105 __CFRunLoopRun + 2405
40 CoreFoundation                 0x7fff9f313544 CFRunLoopRunSpecific + 420
41 HIToolbox                      0x7fff9e872ebc RunCurrentEventLoopInMode + 240
42 HIToolbox                      0x7fff9e872cf1 ReceiveNextEventCommon + 432
43 HIToolbox                      0x7fff9e872b26 _BlockUntilNextEventMatchingListInModeWithFilter + 71
44 AppKit                         0x7fff9ce09a54 _DPSNextEvent + 1120
45 AppKit                         0x7fff9d5857ee -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 2796
46 AppKit                         0x7fff9cdfe3db -[NSApplication run] + 926
47 AppKit                         0x7fff9cdc8e0e NSApplicationMain + 1237
48 libdyld.dylib                  0x7fffb505c235 start + 1

#1. com.twitter.crashlytics.mac.MachExceptionServer
0  libsystem_kernel.dylib         0x7fffb518334a mach_msg_trap + 10
1  libsystem_kernel.dylib         0x7fffb5182797 mach_msg + 55
2  CommandPost                    0x1063757c2 CLSMachExceptionServer + 123
3  libsystem_pthread.dylib        0x7fffb527593b _pthread_body + 180
4  libsystem_pthread.dylib        0x7fffb5275887 _pthread_start + 284
5  libsystem_pthread.dylib        0x7fffb527508d thread_start + 13

#2. com.apple.NSURLConnectionLoader
0  libsystem_kernel.dylib         0x7fffb518334a mach_msg_trap + 10
1  libsystem_kernel.dylib         0x7fffb5182797 mach_msg + 55
2  CoreFoundation                 0x7fff9f314874 __CFRunLoopServiceMachPort + 212
3  CoreFoundation                 0x7fff9f313cf1 __CFRunLoopRun + 1361
4  CoreFoundation                 0x7fff9f313544 CFRunLoopRunSpecific + 420
5  CFNetwork                      0x7fff9e44e344 +[NSURLConnection(Loader) _resourceLoadLoop:] + 313
6  Foundation                     0x7fffa0d548ad __NSThread__start__ + 1243
7  libsystem_pthread.dylib        0x7fffb527593b _pthread_body + 180
8  libsystem_pthread.dylib        0x7fffb5275887 _pthread_start + 284
9  libsystem_pthread.dylib        0x7fffb527508d thread_start + 13

#3. com.apple.NSEventThread
0  libsystem_kernel.dylib         0x7fffb518334a mach_msg_trap + 10
1  libsystem_kernel.dylib         0x7fffb5182797 mach_msg + 55
2  CoreFoundation                 0x7fff9f314874 __CFRunLoopServiceMachPort + 212
3  CoreFoundation                 0x7fff9f313cf1 __CFRunLoopRun + 1361
4  CoreFoundation                 0x7fff9f313544 CFRunLoopRunSpecific + 420
5  AppKit                         0x7fff9cf56f02 _NSEventThread + 205
6  libsystem_pthread.dylib        0x7fffb527593b _pthread_body + 180
7  libsystem_pthread.dylib        0x7fffb5275887 _pthread_start + 284
8  libsystem_pthread.dylib        0x7fffb527508d thread_start + 13

#4. Thread
0  libsystem_kernel.dylib         0x7fffb518abf2 __psynch_cvwait + 10
1  libsystem_pthread.dylib        0x7fffb52767fa _pthread_cond_wait + 712
2  libc++.1.dylib                 0x7fffb3bf94cd std::__1::condition_variable::wait(std::__1::unique_lock<std::__1::mutex>&) + 47
3  JavaScriptCore                 0x7fffa234243c void std::__1::condition_variable_any::wait<std::__1::unique_lock<bmalloc::Mutex> >(std::__1::unique_lock<bmalloc::Mutex>&) + 108
4  JavaScriptCore                 0x7fffa23423bb bmalloc::AsyncTask<bmalloc::Heap, void (bmalloc::Heap::*)()>::threadRunLoop() + 155
5  JavaScriptCore                 0x7fffa234228d bmalloc::AsyncTask<bmalloc::Heap, void (bmalloc::Heap::*)()>::threadEntryPoint(bmalloc::AsyncTask<bmalloc::Heap, void (bmalloc::Heap::*)()>*) + 29
6  JavaScriptCore                 0x7fffa234253d void* std::__1::__thread_proxy<std::__1::tuple<void (*)(bmalloc::AsyncTask<bmalloc::Heap, void (bmalloc::Heap::*)()>*), bmalloc::AsyncTask<bmalloc::Heap, void (bmalloc::Heap::*)()>*> >(void*) + 93
7  libsystem_pthread.dylib        0x7fffb527593b _pthread_body + 180
8  libsystem_pthread.dylib        0x7fffb5275887 _pthread_start + 284
9  libsystem_pthread.dylib        0x7fffb527508d thread_start + 13

#5. com.apple.coreanimation.render-server
0  libsystem_kernel.dylib         0x7fffb518334a mach_msg_trap + 10
1  libsystem_kernel.dylib         0x7fffb5182797 mach_msg + 55
2  QuartzCore                     0x7fffa5429bd4 CA::Render::Server::server_thread(void*) + 272
3  QuartzCore                     0x7fffa54da3ab thread_fun + 25
4  libsystem_pthread.dylib        0x7fffb527593b _pthread_body + 180
5  libsystem_pthread.dylib        0x7fffb5275887 _pthread_start + 284
6  libsystem_pthread.dylib        0x7fffb527508d thread_start + 13

#6. Thread
0  libsystem_kernel.dylib         0x7fffb518334a mach_msg_trap + 10
1  libsystem_kernel.dylib         0x7fffb5182797 mach_msg + 55
2  CoreMIDI                       0x1065949c1 XServerMachPort::ReceiveMessage(int&, void*, int&) + 107
3  CoreMIDI                       0x1065aaba9 MIDIProcess::RunMIDIInThread() + 105
4  CoreMIDI                       0x1065b7a9a XThread::RunHelper(void*) + 10
5  CoreMIDI                       0x1065bb053 CAPThread::Entry(CAPThread*) + 85
6  libsystem_pthread.dylib        0x7fffb527593b _pthread_body + 180
7  libsystem_pthread.dylib        0x7fffb5275887 _pthread_start + 284
8  libsystem_pthread.dylib        0x7fffb527508d thread_start + 13

#7. Thread
0  libsystem_kernel.dylib         0x7fffb518334a mach_msg_trap + 10
1  libsystem_kernel.dylib         0x7fffb5182797 mach_msg + 55
2  CoreFoundation                 0x7fff9f314874 __CFRunLoopServiceMachPort + 212
3  CoreFoundation                 0x7fff9f313cf1 __CFRunLoopRun + 1361
4  CoreFoundation                 0x7fff9f313544 CFRunLoopRunSpecific + 420
5  CoreFoundation                 0x7fff9f352d31 CFRunLoopRun + 97
6  MultitouchSupport              0x7fffaf39eed4 mt_ThreadedMTEntry + 71
7  libsystem_pthread.dylib        0x7fffb527593b _pthread_body + 180
8  libsystem_pthread.dylib        0x7fffb5275887 _pthread_start + 284
9  libsystem_pthread.dylib        0x7fffb527508d thread_start + 13

#8. Thread
0  libsystem_kernel.dylib         0x7fffb518b44e __workq_kernreturn + 10
1  libsystem_pthread.dylib        0x7fffb5275621 _pthread_wqthread + 1426
2  libsystem_pthread.dylib        0x7fffb527507d start_wqthread + 13

#9. Thread
0  libsystem_kernel.dylib         0x7fffb518b44e __workq_kernreturn + 10
1  libsystem_pthread.dylib        0x7fffb5275621 _pthread_wqthread + 1426
2  libsystem_pthread.dylib        0x7fffb527507d start_wqthread + 13

#10. Thread
0  libsystem_kernel.dylib         0x7fffb518339e semaphore_timedwait_trap + 10
1  libdispatch.dylib              0x7fffb503eb09 _os_semaphore_timedwait + 72
2  libdispatch.dylib              0x7fffb502f864 _dispatch_semaphore_wait_slow + 58
3  libdispatch.dylib              0x7fffb502a290 _dispatch_worker_thread + 275
4  libsystem_pthread.dylib        0x7fffb527593b _pthread_body + 180
5  libsystem_pthread.dylib        0x7fffb5275887 _pthread_start + 284
6  libsystem_pthread.dylib        0x7fffb527508d thread_start + 13
cmsj commented 6 years ago

looks like it was trying to log a date to the console and something deep in the icu stack crashed. Do we have any idea what was happening at the time?

latenitefilms commented 6 years ago

Sorry - no idea to be honest.

asmagill commented 6 years ago

0. Crashed: com.apple.main-thread

0 libsystem_kernel.dylib 0x7fffb518ad42 __pthread_kill + 10 1 libsystem_pthread.dylib 0x7fffb5278457 pthread_kill + 90 2 libsystem_c.dylib 0x7fffb50f0420 abort + 129 3 libsystem_malloc.dylib 0x7fffb51eaf5d szone_error + 626 4 libsystem_malloc.dylib 0x7fffb51ec925 small_free_list_remove_ptr_no_clear + 766 5 libsystem_malloc.dylib 0x7fffb51e0823 small_malloc_from_free_list + 159 6 libsystem_malloc.dylib 0x7fffb51de953 szone_malloc_should_clear + 1649 7 libsystem_malloc.dylib 0x7fffb51de282 malloc_zone_malloc + 107 8 libsystem_malloc.dylib 0x7fffb51dd200 malloc + 24

This indicates that it was trying to allocate a block of memory and never returned from the request, so as far as the application was concerned, it ran out of memory. As to why it was under memory pressure and whether or not it was caused by some other problem in Hammerspoon or the applications running on the machine or if it truly was out of memory or what, I couldn't tell you. There are some tools within XCode that will let you check for things like memory leaks and such that might help indicate if there is something in Hammerspoon we could be managing better; I'm just beginning to understand how to work with them, so by telling you they exist, I've about reached the level of help I can offer in how they work and how to use them :-) ... maybe @cmsj has some suggestions on what might be worth looking at first.

cmsj commented 6 years ago

It doesn't necessarily mean it ran out of memory - heap corruption could be causing a sanity check to blow up.

Given the number of weird crashes we get, I've long suspected that we have a heap corruption bug (or more than one!) in HS, but I really have no idea where to even begin looking for it.

cmsj commented 6 years ago

@latenitefilms do you think any/many CommandPost people are customising their configs? Or is it very much intended to run fully stock?

My thinking here is that we have a lot of code - HS is in total about 100,000 lines of code, but only about 1/5 of that is plain C, which is where I would expect heap corruptions to be coming from. If we exclude third party dependencies (a questionable choice) we're down to ~40,000 lines, of which only ~5000 are plain C. We need more ways to reduce the search space, and if CP is fairly static, that narrows down the number of modules to be considered.

latenitefilms commented 6 years ago

No, very, very few people are modifying their configs. Apart from David and myself I can think of only one other person I know of that’s writing custom plugins for CommandPost in Lua.

asmagill commented 6 years ago

Fair enough -- something is preventing malloc from returning a block the size requested, and a severely fragmented or corrupt heap could definitely do that. However, the header to the dump does say that free ram was < 1%... though I don't know whether that report factors out file caches from the free ram or not, so... it may be a completely irrelevant measure.

I do agree that heap corruption is probably something we need to look into, though; just not sure how at this point, so I'll let you drive that for now :-)

cmsj commented 6 years ago

@latenitefilms ok, would you be able to figure out a list of the extensions it imports? (no immediate rush)

I have another thought here, which is that I think I might start recording in Crashlytics which extensions people load, so at least in a crash scenario we can see what code is present. Any objections?

asmagill commented 6 years ago

WRT to core modules, no objections; wrt to third party, does our privacy policy say anything? do we have a privacy policy? I know we've talked about privacy a few times in the past, but I guess I never looked -- I should maybe look at the projects official web site once in a while :-)

In practice, I suspect most of the third party modules are written by me, and I don't have an issue with them being included in such a list, but if someone is working on their own or using other modules from other sources... would that constitute "identifying information"? Do we need to make it an opt in/out?

cmsj commented 6 years ago

@asmagill there's a button for the privacy policy right in the Preferences window 😁 As for the source of the modules, we could probably figure it out and choose to exclude things not coming from Hammerspoon.app

asmagill commented 6 years ago

sheepish grin oh yeah...

I wouldn't mind if my particular modules (all of which start with hs._asm) are included... many of them end up in core and @latenitefilms uses a lot of them as well. But as a policy, I think that's probably a good idea... maybe a list which a module can add it self to at load time or a user can from the console -- that way we could even ask people to add it if we suspect a third party module might be causing someone's problems.

Of course I don't know exactly what your proposal will entail, so if this is too complex or arbitrary, then just do the core.

latenitefilms commented 6 years ago

Is there a command I can type in the Console to return a list of all active extensions?

The only 3rd party Objective-C extensions we're using are hs._asm.axuielement, hs._asm.undocumented.touchbar and hs._asm.undocumented.touchdevice. All our other extensions are just Lua.

latenitefilms commented 6 years ago

Maybe you could also have an option (off by default) that sends the Console contents as part of Crashlytics?

cmsj commented 6 years ago

@latenitefilms I think this will show the list: for key,val in pairs(package.loaded) do print(key..":"..type(val)) end

latenitefilms commented 6 years ago

Here you go:

> for key,val in pairs(package.loaded) do print(key..":"..type(val)) end
2018-01-17 09:17:46: cp.apple.finalcutpro.windowfilter:table
2018-01-17 09:17:46: cp.ids:table
2018-01-17 09:17:46: hs.timer:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector:table
2018-01-17 09:17:46: hs._asm.axuielement.internal:table
2018-01-17 09:17:46: hs.timer.internal:table
2018-01-17 09:17:46: coroutine:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.InfoInspector:table
2018-01-17 09:17:46: hs.tangent:table
2018-01-17 09:17:46: cp.sourcewatcher:table
2018-01-17 09:17:46: cp.apple.finalcutpro.MenuBar:table
2018-01-17 09:17:46: cp.utf16.be:table
2018-01-17 09:17:46: hs.spaces.watcher:table
2018-01-17 09:17:46: hs.dialog.internal:table
2018-01-17 09:17:46: math:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.TextInspector:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.AudioInspector:table
2018-01-17 09:17:46: table:table
2018-01-17 09:17:46: hs.hints:table
2018-01-17 09:17:46: hs.screen:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.ColorInspector.HueSaturationCurves:table
2018-01-17 09:17:46: hs.httpserver.hsminweb:table
2018-01-17 09:17:46: hs.distributednotifications:table
2018-01-17 09:17:46: hs._asm.undocumented.touchdevice:table
2018-01-17 09:17:46: hs._asm.undocumented.touchdevice.forcetouch:table
2018-01-17 09:17:46: debug:table
2018-01-17 09:17:46: hs.eventtap:table
2018-01-17 09:17:46: cp.ui.Button:table
2018-01-17 09:17:46: hs.urlevent:table
2018-01-17 09:17:46: cp.localized:table
2018-01-17 09:17:46: hs._coresetup:table
2018-01-17 09:17:46: cp.plist.plistParse:function
2018-01-17 09:17:46: hs.task.internal:table
2018-01-17 09:17:46: hs.streamdeck:table
2018-01-17 09:17:46: hs.streamdeck.internal:table
2018-01-17 09:17:46: hs.host.internal:table
2018-01-17 09:17:46: hs.network.host:table
2018-01-17 09:17:46: hs.network.hostinternal:table
2018-01-17 09:17:46: hs.hints.internal:table
2018-01-17 09:17:46: hs.midi:table
2018-01-17 09:17:46: hs.chooser.internal:table
2018-01-17 09:17:46: hs.application.internal:table
2018-01-17 09:17:46: hs.fs.internal:table
2018-01-17 09:17:46: cp.ui.RadioButton:table
2018-01-17 09:17:46: hs.midi.internal:table
2018-01-17 09:17:46: string:table
2018-01-17 09:17:46: hs.sound.internal:table
2018-01-17 09:17:46: hs.canvas.internal:table
2018-01-17 09:17:46: hs.fs:table
2018-01-17 09:17:46: cp.apple.finalcutpro.prefs.PlaybackPanel:table
2018-01-17 09:17:46: hs.dialog:table
2018-01-17 09:17:46: mimetypes:table
2018-01-17 09:17:46: cp.web.html:table
2018-01-17 09:17:46: hs.crash:table
2018-01-17 09:17:46: hs.window.filter:table
2018-01-17 09:17:46: i18n:table
2018-01-17 09:17:46: hs.host:table
2018-01-17 09:17:46: hs.screen.watcher:table
2018-01-17 09:17:46: hs.window:table
2018-01-17 09:17:46: cp.apple.finalcutpro.import.MediaImport:table
2018-01-17 09:17:46: hs.alert:table
2018-01-17 09:17:46: hs.fs.volume:table
2018-01-17 09:17:46: hs.audiodevice.internal:table
2018-01-17 09:17:46: hs.sharing.internal:table
2018-01-17 09:17:46: cp.just:table
2018-01-17 09:17:46: cp.bench:table
2018-01-17 09:17:46: hs.messages:table
2018-01-17 09:17:46: hs.webview.internal:table
2018-01-17 09:17:46: hs.eventtap.internal:table
2018-01-17 09:17:46: hs.http:table
2018-01-17 09:17:46: cp.strings:table
2018-01-17 09:17:46: moses:table
2018-01-17 09:17:46: i18n.interpolate:function
2018-01-17 09:17:46: slaxml.slaxml:table
2018-01-17 09:17:46: cp.plugins:table
2018-01-17 09:17:46: cp.apple.finalcutpro.cmd.CommandEditor:table
2018-01-17 09:17:46: hs.webview.datastore:table
2018-01-17 09:17:46: cp.text.matcher:function
2018-01-17 09:17:46: slaxml.slaxdom:table
2018-01-17 09:17:46: cp.watcher:table
2018-01-17 09:17:46: hs.httpserver.cgilua_compatibility_functions:table
2018-01-17 09:17:46: hs.uielement.internal:table
2018-01-17 09:17:46: cp.apple.compressor:table
2018-01-17 09:17:46: hs.styledtext:table
2018-01-17 09:17:46: hs.base64:table
2018-01-17 09:17:46: hs.styledtext.internal:table
2018-01-17 09:17:46: hs.speech.listener:table
2018-01-17 09:17:46: hs.speech.internal:table
2018-01-17 09:17:46: cp.apple.finalcutpro.export.ExportDialog:table
2018-01-17 09:17:46: cp.feedback:table
2018-01-17 09:17:46: cp.idle:table
2018-01-17 09:17:46: hs.doc:table
2018-01-17 09:17:46: hs.json:table
2018-01-17 09:17:46: cp.commands.englishKeyCodes:table
2018-01-17 09:17:46: hs._asm.undocumented.touchbar.supported:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.LibrariesBrowser:table
2018-01-17 09:17:46: hs._asm.undocumented.touchbar:table
2018-01-17 09:17:46: hs.chooser:table
2018-01-17 09:17:46: hs.pasteboard:table
2018-01-17 09:17:46: hs.sound:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.EffectInspector:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.LibrariesList:table
2018-01-17 09:17:46: cp.apple.finalcutpro.plugins.guiscan:table
2018-01-17 09:17:46: hs.doc.spoonsupport:table
2018-01-17 09:17:46: hs.watchable:table
2018-01-17 09:17:46: cp.commands:table
2018-01-17 09:17:46: cp.apple.finalcutpro.plugins:table
2018-01-17 09:17:46: hs.pathwatcher.internal:table
2018-01-17 09:17:46: hs.mouse:table
2018-01-17 09:17:46: hs.socket:table
2018-01-17 09:17:46: hs.socket.udp:table
2018-01-17 09:17:46: cp.apple.finalcutpro.prefs.PreferencesWindow:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.TransitionInspector:table
2018-01-17 09:17:46: package:table
2018-01-17 09:17:46: cp.ui.CheckBox:table
2018-01-17 09:17:46: hs.socket.internal:table
2018-01-17 09:17:46: hs.canvas:table
2018-01-17 09:17:46: hs.canvas.matrix:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.TimelineAppearance:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Playhead:table
2018-01-17 09:17:46: hs.host.locale.internal:table
2018-01-17 09:17:46: cp.web.ui:table
2018-01-17 09:17:46: hs.menubar.internal:table
2018-01-17 09:17:46: hs._asm.undocumented.touchbar.bar:table
2018-01-17 09:17:46: cp.strings.source.plist:table
2018-01-17 09:17:46: hs.notify:table
2018-01-17 09:17:46: hs._asm.undocumented.touchbar.internal:table
2018-01-17 09:17:46: cp.plugins.plugin:table
2018-01-17 09:17:46: hs.crash.internal:table
2018-01-17 09:17:46: hs.menubar:table
2018-01-17 09:17:46: hs.settings.internal:table
2018-01-17 09:17:46: cp.developer:boolean
2018-01-17 09:17:46: cp.dialog:table
2018-01-17 09:17:46: cp.web.text:table
2018-01-17 09:17:46: hs.canvas.matrix_internal:table
2018-01-17 09:17:46: hs.sharing:table
2018-01-17 09:17:46: hs.speech:table
2018-01-17 09:17:46: hs.applescript:table
2018-01-17 09:17:46: hs.base64.internal:table
2018-01-17 09:17:46: cp.utf16:table
2018-01-17 09:17:46: hs.utf8:table
2018-01-17 09:17:46: cp.utf16.le:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.GeneratorInspector:table
2018-01-17 09:17:46: cp.ui.Slider:table
2018-01-17 09:17:46: hs.webview.usercontent:table
2018-01-17 09:17:46: hs.task:table
2018-01-17 09:17:46: cp.plugins.env:table
2018-01-17 09:17:46: _G:table
2018-01-17 09:17:46: hs.inspect:table
2018-01-17 09:17:46: cp.apple.finalcutpro:table
2018-01-17 09:17:46: hs.drawing:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Browser:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.FullScreenWindow:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.TimelineContents:table
2018-01-17 09:17:46: cp.text:table
2018-01-17 09:17:46: cp.apple.finalcutpro.content.Clip:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.VideoInspector:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.ShareInspector:table
2018-01-17 09:17:46: i18n.variants:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Viewer:table
2018-01-17 09:17:46: hs.urlevent.internal:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.TimelineToolbar:table
2018-01-17 09:17:46: hs.http.internal:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.ColorInspector.ColorWheels:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.ColorInspector:table
2018-01-17 09:17:46: hs.audiodevice:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.EffectsBrowser:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.MediaBrowser:table
2018-01-17 09:17:46: hs.fnutils:table
2018-01-17 09:17:46: cp.apple.finalcutpro.export.ReplaceAlert:table
2018-01-17 09:17:46: cp.apple.finalcutpro.export.GoToPrompt:table
2018-01-17 09:17:46: resty.template:table
2018-01-17 09:17:46: cp.plist.archiver:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.GeneratorsBrowser:table
2018-01-17 09:17:46: hs.image.internal:table
2018-01-17 09:17:46: io:table
2018-01-17 09:17:46: hs.host.locale:table
2018-01-17 09:17:46: cp.apple.finalcutpro.export.SaveSheet:table
2018-01-17 09:17:46: cp.ui.PopUpButton:table
2018-01-17 09:17:46: cp.ui.ScrollArea:table
2018-01-17 09:17:46: cp.ui.TextField:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.LibrariesFilmstrip:table
2018-01-17 09:17:46: hs.keycodes:table
2018-01-17 09:17:46: cp.ui.axutils:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.SecondaryWindow:table
2018-01-17 09:17:46: hs.drawing.color:table
2018-01-17 09:17:46: hs.eventtap.event:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.PrimaryWindow:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.ColorBoard:table
2018-01-17 09:17:46: hs.application:table
2018-01-17 09:17:46: hs.hotkey.internal:table
2018-01-17 09:17:46: hs.console.internal:table
2018-01-17 09:17:46: hs.settings:table
2018-01-17 09:17:46: hs._asm.undocumented.touchbar.item:table
2018-01-17 09:17:46: hs.webview.toolbar:table
2018-01-17 09:17:46: cp.protect:function
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.TitleInspector:table
2018-01-17 09:17:46: cp.apple.finalcutpro.export.destinations:table
2018-01-17 09:17:46: cp.apple.finalcutpro.WindowWatcher:table
2018-01-17 09:17:46: hs._asm.axuielement:table
2018-01-17 09:17:46: hs.pasteboard.internal:table
2018-01-17 09:17:46: hs.osascript:table
2018-01-17 09:17:46: cp.apple.finalcutpro.prefs.ImportPanel:table
2018-01-17 09:17:46: hs.distributednotifications.internal:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.ColorInspector.ColorCurves:table
2018-01-17 09:17:46: cp.apple.finalcutpro.keycodes:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Inspector.ColorInspector.ColorBoard:table
2018-01-17 09:17:46: hs.pathwatcher:table
2018-01-17 09:17:46: hs.notify.internal:table
2018-01-17 09:17:46: semver:table
2018-01-17 09:17:46: hs.uielement:table
2018-01-17 09:17:46: hs.ipc:table
2018-01-17 09:17:46: cp.ui.Window:table
2018-01-17 09:17:46: cp.tools:table
2018-01-17 09:17:46: hs.osascript.internal:table
2018-01-17 09:17:46: hs.screen.internal:table
2018-01-17 09:17:46: hs.spaces:table
2018-01-17 09:17:46: cp.ui.Table:table
2018-01-17 09:17:46: hs.keycodes.internal:table
2018-01-17 09:17:46: cp.prop:table
2018-01-17 09:17:46: cp.apple.finalcutpro.ids:table
2018-01-17 09:17:46: cp.commands.shortcut:table
2018-01-17 09:17:46: os:table
2018-01-17 09:17:46: hs.hotkey:table
2018-01-17 09:17:46: hs.ipc.internal:table
2018-01-17 09:17:46: hs.audiodevice.watcher:table
2018-01-17 09:17:46: hs.drawing.internal:table
2018-01-17 09:17:46: hs.geometry:table
2018-01-17 09:17:46: cp.plist:table
2018-01-17 09:17:46: hs.image:table
2018-01-17 09:17:46: hs.logger:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.Timeline:table
2018-01-17 09:17:46: hs.webview:table
2018-01-17 09:17:46: hs.drawing.color.internal:table
2018-01-17 09:17:46: hs.webview.toolbar_internal:table
2018-01-17 09:17:46: hs._asm.undocumented.touchdevice.internal:table
2018-01-17 09:17:46: i18n.plural:table
2018-01-17 09:17:46: utf8:table
2018-01-17 09:17:46: hs.console:table
2018-01-17 09:17:46: cp.commands.command:table
2018-01-17 09:17:46: i18n.version:string
2018-01-17 09:17:46: cp.choices:table
2018-01-17 09:17:46: hs.doc.builder:table
2018-01-17 09:17:46: hs.application.watcher:table
2018-01-17 09:17:46: hs.window.internal:table
2018-01-17 09:17:46: cp.config:table
2018-01-17 09:17:46: cp.apple.finalcutpro.main.ColorPucker:table
2018-01-17 09:17:46: hs.json.internal:table
2018-01-17 09:17:46: hs.fs.xattr:table
2018-01-17 09:17:46: hs.mouse.internal:table
cmsj commented 6 years ago

wow :)

cmsj commented 6 years ago

Ok, so let's do some scope narrowing here.

We know the crashes happen in HS as well as CP, so we can filter out your modules. I also suspect (although I can't prove it since I didn't fix the crashlogging properly in 0.9.59) that the crashes happen without any hs._asm modules. Eliminating those modules and cross referencing that with what's loaded in my setup (which I can't say doesn't ever crash, but at least doesn't seem to crash very much at all) gives us the following modules that CP loads, which I don't:

So nothing is jumping out as high risk. There is also, of course, the core of Hammerspoon itself, and LuaSkin, both of which are fairly complex (especially LuaSkin).

I'll try and get 0.9.60 out soon with a fix for the crashlogging, and maybe we can narrow the list further.

latenitefilms commented 6 years ago

Is it worth updating CocoaAsyncSocket from 7.4.3 to 7.6.2 in case there’s any bugs in there?

cmsj commented 6 years ago

@latenitefilms yeah, it may well be.

I'm also going to commit some changes to the Hammerspoon build scheme that enable Address Sanitiser. I've already found two heap issues with it running my config, although sadly I don't think either are related to the crashes we've been seeing, but I would encourage @latenitefilms and @asmagill to do some extensive usage of HS/CP with these settings applied, and see what pops up for you.

cmsj commented 6 years ago

@asmagill got another hit from Address Sanitizer:

2018-01-31 13:46:00.334015+0000 Hammerspoon[10355:32711949] /Users/cmsj/hacking/hammerspoon/hammerspoon/extensions/doc/autolink.c:277:40: runtime error: addition of unsigned offset to 0x617000516f21 overflowed to 0x617000516f20
2018-01-31 13:46:00.334056+0000 Hammerspoon[10355:32711949] SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior /Users/cmsj/hacking/hammerspoon/hammerspoon/extensions/doc/autolink.c:277:40 in
cmsj commented 6 years ago

(that may not actually be a genuine bug, it may just be the rather odd construct of the loop)

cmsj commented 6 years ago

ok, so I'm just going to rubberducky some stuff in here, in the hopes that it helps.

I've found a pretty reliable heap-use-after-free AddressSanitizer issue, which I think is actually a heap corruption. I'm surprised by how reliable the cause and effect are, but I suspect that may just be down to the code addresses that are being produced by my current builds.

To trigger the issue, I've got an hs.audiodevice.watcher watcher going, and I'm making a bunch of changes to audio devices (specifically, I connect/disconnect some bluetooth headphones a few times). Then I open the console and click on the help browser window. Something in that giant stack of code seems to overwrite the audiodevice watcher.m theWatcher->callback value from 1 (which makes perfect sense because it's the only thing in the module's refTable, to some very high number (which makes no sense).

This is how I'm working. I tell Xcode to run HS, then when it's finished I pause it with the debugger and run:

(lldb) p theWatcher->callback
(int) $0 = 1
(lldb) expr --raw -- &theWatcher->callback
(int *) $1 = 0x00006040003f7138
(lldb) w s e -- 0x00006040003f7138
Watchpoint created: Watchpoint 1: addr = 0x6040003f7138 size = 8 state = enabled type = w
    new value: -4702112049423974399
(lldb) watch set variable theWatcher->callback
Watchpoint created: Watchpoint 2: addr = 0x6040003f7138 size = 4 state = enabled type = w
    watchpoint spec = 'theWatcher->callback'
    new value: 1
(lldb) c

This shows the current value of theWatcher->callback, then gets its address in memory, then sets a watchpoint on that memory, then sets a watchpoint on the variable, then continues execution of HS.

I then open the console and click on the Help toolbar item. At this point a bunch of stuff loads and then the second watchpoint gets hit and execution pauses:

<lots of requires snipped>
2018-01-31 14:35:45.453902+0000 Hammerspoon[17824:32984152] require: hs.doc.markdown
2018-01-31 14:35:45.460204+0000 Hammerspoon[17824:32984152] require: hs.doc.markdown

Watchpoint 2 hit:
old value: 1
new value: 1431655765
(lldb) 

The backtrace at this point shows an HSHTTPConnection httpResponseForMethod callback block at the very bottom, with then a bunch of lua things above, and interestingly, some GC stuff near the top:

(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = watchpoint 2
    frame #0: 0x00007fff511b9cb7 libsystem_platform.dylib`_platform_bzero$VARIANT$Haswell + 119
    frame #1: 0x00000001007cdb7b libclang_rt.asan_osx_dynamic.dylib`__asan::Allocator::QuarantineChunk(__asan::AsanChunk*, void*, __sanitizer::BufferedStackTrace*, __asan::AllocType) + 203
    frame #2: 0x000000010081f131 libclang_rt.asan_osx_dynamic.dylib`wrap_free + 401
    frame #3: 0x00000001017ddd7c LuaSkin`l_alloc(ud=0x0000000000000000, ptr=0x00006040003f7110, osize=48, nsize=0) at lauxlib.c:1011
    frame #4: 0x00000001017df0eb LuaSkin`luaM_realloc_(L=0x000061b00008d588, block=0x00006040003f7110, osize=48, nsize=0) at lmem.c:86
    frame #5: 0x0000000101720975 LuaSkin`freeobj(L=0x000061b00008d588, o=0x00006040003f7110) at lgc.c:709
    frame #6: 0x000000010171a373 LuaSkin`sweeplist(L=0x000061b00008d588, p=0x0000608000194da0, count=16) at lgc.c:743
    frame #7: 0x0000000101724e60 LuaSkin`sweepstep(L=0x000061b00008d588, g=0x000061b00008d658, nextstate=3, nextlist=0x000061b00008d6c0) at lgc.c:1032
    frame #8: 0x000000010171b43a LuaSkin`singlestep(L=0x000061b00008d588) at lgc.c:1070
    frame #9: 0x000000010171c067 LuaSkin`luaC_step(L=0x000061b00008d588) at lgc.c:1136
    frame #10: 0x0000000101680b0c LuaSkin`luaV_execute(L=0x000061b00008d588) at lvm.c:1076
    frame #11: 0x00000001016b191b LuaSkin`luaD_call(L=0x000061b00008d588, func=0x000061f000141560, nResults=-1) at ldo.c:516
    frame #12: 0x00000001016b1cc1 LuaSkin`luaD_callnoyield(L=0x000061b00008d588, func=0x000061f000141560, nResults=-1) at ldo.c:526
    frame #13: 0x00000001017766f6 LuaSkin`f_call(L=0x000061b00008d588, ud=0x00007ffeefbef520) at lapi.c:942
    frame #14: 0x00000001016f7fd7 LuaSkin`luai_objcttry(L=0x000061b00008d588, c_lua_longjmp=0x00007ffeefbef220, a_func=(LuaSkin`f_call at lapi.c:940), userdata=0x00007ffeefbef520) at lobjectivec_exceptions.m:84
    frame #15: 0x00000001016a6a19 LuaSkin`luaD_rawrunprotected(L=0x000061b00008d588, f=(LuaSkin`f_call at lapi.c:940), ud=0x00007ffeefbef520) at ldo.c:156
    frame #16: 0x00000001016b6921 LuaSkin`luaD_pcall(L=0x000061b00008d588, func=(LuaSkin`f_call at lapi.c:940), u=0x00007ffeefbef520, old_top=736, ef=704) at ldo.c:746
    frame #17: 0x0000000101774f9d LuaSkin`lua_pcallk(L=0x000061b00008d588, nargs=0, nresults=-1, errfunc=2, ctx=2, k=(LuaSkin`finishpcall at lbaselib.c:408)) at lapi.c:968
    frame #18: 0x0000000101737f8f LuaSkin`luaB_xpcall(L=0x000061b00008d588) at lbaselib.c:441
    frame #19: 0x00000001016adc0e LuaSkin`luaD_precall(L=0x000061b00008d588, func=0x000061f000141520, nresults=2) at ldo.c:451
    frame #20: 0x0000000101688045 LuaSkin`luaV_execute(L=0x000061b00008d588) at lvm.c:1134
    frame #21: 0x00000001016b191b LuaSkin`luaD_call(L=0x000061b00008d588, func=0x000061f000141390, nResults=-1) at ldo.c:516
    frame #22: 0x00000001016b1cc1 LuaSkin`luaD_callnoyield(L=0x000061b00008d588, func=0x000061f000141390, nResults=-1) at ldo.c:526
    frame #23: 0x00000001017766f6 LuaSkin`f_call(L=0x000061b00008d588, ud=0x00007ffeefbf6420) at lapi.c:942
    frame #24: 0x00000001016f7fd7 LuaSkin`luai_objcttry(L=0x000061b00008d588, c_lua_longjmp=0x00007ffeefbf6120, a_func=(LuaSkin`f_call at lapi.c:940), userdata=0x00007ffeefbf6420) at lobjectivec_exceptions.m:84
    frame #25: 0x00000001016a6a19 LuaSkin`luaD_rawrunprotected(L=0x000061b00008d588, f=(LuaSkin`f_call at lapi.c:940), ud=0x00007ffeefbf6420) at ldo.c:156
    frame #26: 0x00000001016b6921 LuaSkin`luaD_pcall(L=0x000061b00008d588, func=(LuaSkin`f_call at lapi.c:940), u=0x00007ffeefbf6420, old_top=272, ef=240) at ldo.c:746
    frame #27: 0x0000000101774f9d LuaSkin`lua_pcallk(L=0x000061b00008d588, nargs=5, nresults=-1, errfunc=2, ctx=2, k=(LuaSkin`finishpcall at lbaselib.c:408)) at lapi.c:968
    frame #28: 0x0000000101737f8f LuaSkin`luaB_xpcall(L=0x000061b00008d588) at lbaselib.c:441
    frame #29: 0x00000001016adc0e LuaSkin`luaD_precall(L=0x000061b00008d588, func=0x000061f000141350, nresults=-1) at ldo.c:451
    frame #30: 0x0000000101688045 LuaSkin`luaV_execute(L=0x000061b00008d588) at lvm.c:1134
    frame #31: 0x00000001016b191b LuaSkin`luaD_call(L=0x000061b00008d588, func=0x000061f0001412a0, nResults=3) at ldo.c:516
    frame #32: 0x00000001016b1cc1 LuaSkin`luaD_callnoyield(L=0x000061b00008d588, func=0x000061f0001412a0, nResults=3) at ldo.c:526
    frame #33: 0x00000001017766f6 LuaSkin`f_call(L=0x000061b00008d588, ud=0x00007ffeefbfd320) at lapi.c:942
    frame #34: 0x00000001016f7fd7 LuaSkin`luai_objcttry(L=0x000061b00008d588, c_lua_longjmp=0x00007ffeefbfd020, a_func=(LuaSkin`f_call at lapi.c:940), userdata=0x00007ffeefbfd320) at lobjectivec_exceptions.m:84
    frame #35: 0x00000001016a6a19 LuaSkin`luaD_rawrunprotected(L=0x000061b00008d588, f=(LuaSkin`f_call at lapi.c:940), ud=0x00007ffeefbfd320) at ldo.c:156
    frame #36: 0x00000001016b6921 LuaSkin`luaD_pcall(L=0x000061b00008d588, func=(LuaSkin`f_call at lapi.c:940), u=0x00007ffeefbfd320, old_top=32, ef=16) at ldo.c:746
    frame #37: 0x0000000101774f9d LuaSkin`lua_pcallk(L=0x000061b00008d588, nargs=4, nresults=3, errfunc=-6, ctx=0, k=0x0000000000000000) at lapi.c:968
    frame #38: 0x00000001016288e3 LuaSkin`-[LuaSkin protectedCallAndTraceback:nresults:](self=0x00006070000942f0, _cmd="protectedCallAndTraceback:nresults:", nargs=4, nresults=3) at Skin.m:227
  * frame #39: 0x000000010f0952ce internal.so`__46-[HSHTTPConnection httpResponseForMethod:URI:]_block_invoke(.block_descriptor=<unavailable>) at internal.m:183
    frame #40: 0x00000001018b5d1f libdispatch.dylib`_dispatch_client_callout + 8
    frame #41: 0x00000001018ce93f libdispatch.dylib`_dispatch_sync_thread_bound_invoke + 339
    frame #42: 0x00000001018b5d1f libdispatch.dylib`_dispatch_client_callout + 8
    frame #43: 0x00000001018c1d9d libdispatch.dylib`_dispatch_main_queue_callback_4CF + 549
    frame #44: 0x00007fff2966f7a9 CoreFoundation`__CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ + 9
    frame #45: 0x00007fff296319ca CoreFoundation`__CFRunLoopRun + 2586
    frame #46: 0x00007fff29630d23 CoreFoundation`CFRunLoopRunSpecific + 483
    frame #47: 0x00007fff28948e26 HIToolbox`RunCurrentEventLoopInMode + 286
    frame #48: 0x00007fff28948b96 HIToolbox`ReceiveNextEventCommon + 613
    frame #49: 0x00007fff28948914 HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter + 64
    frame #50: 0x00007fff26c13f5f AppKit`_DPSNextEvent + 2085
    frame #51: 0x00007fff273a9b4c AppKit`-[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 3044
    frame #52: 0x00007fff26c08d6d AppKit`-[NSApplication run] + 764
    frame #53: 0x00007fff26bd7f1a AppKit`NSApplicationMain + 804
    frame #54: 0x000000010000d162 Hammerspoon`main(argc=5, argv=0x00007ffeefbff510) at MJAppDelegate.m:374
    frame #55: 0x00007fff50f34115 libdyld.dylib`start + 1
(lldb) 

Not yet sure where to go from here, but I don't see anything in the httpResponseForMethod callback that seems wrong, so I guess my next step will be to breakpoint on that callback and step down the ~38 levels of backtrace until I find something pointing at the same bit of memory that theWatcher->callback is using.

cmsj commented 6 years ago

Even thought the new value of theWatcher->callback makes no sense as a Lua ref, it still got me thinking about the way we do refTable stuff, and I noticed that a lot of modules declare int refTable without static, which I think is very wrong, so I'm about to push a commit which switches them all to static. Edit: but that doesn't do anything to fix this issue.

asmagill commented 6 years ago

(Sorry I've been slipping in and out of the recent discussions -- I think my schedule is stabilizing so I can spend some real time helping out, so that should change soon)

Something to add to the "TODO Someday" -- I just wanted to slip in that most of the C code portions in hs.doc (e.g. the autolink.c file noted above) are straight from the original ruby(?) module we used to convert the HS doc strings to HTML... It's been a low priority, but eventually that should be changed to the python module (Or something else entirely -- it just needs to be able to convert markdown (preferably with support for the github extensions) to plain text and html) we're using now (a) to maintain parity between the hosted docs and the internally provided ones, and (b) because the ruby version is no longer being maintained, so won't get updates or bug fixes.

cmsj commented 6 years ago

Well then. That was some fun debugging. After stepping through a lot of Lua code and being thoroughly confused, it finally dawned on me that I was looking at backtraces that were GCing a userdata object.... but hs.audiodevice.watcher isn't a userdata object :)

Fixed that particular bug with a2a9b763.

I think I am now going to strongly recommend that anyone who works on the HS code, run with Address Sanitizer (and the other bits I enabled in b5efc2915efa72086e241b2bdd6a72a383b3841f ) and probably that we should all add a collectgarbage() at the end of our init.lua. The performance overhead of the debugging features is very low, and in one day it's found two genuine bugs with my config, and suggested another bug may exist.

latenitefilms commented 6 years ago

Just to clarify, do I need to change anything or do anything to enable this, or will the latest Hammerspoon code automatically just write these errors to the Hammerspoon Console?

cmsj commented 6 years ago

@latenitefilms the memory debugging messages would show up in Xcode's log area, if you're running the build from Xcode. Possibly in the system logs otherwise, but I don't know about that.