hammerspoon icon indicating copy to clipboard operation
hammerspoon copied to clipboard

Suggestions for debugging an infrequently hanging Hammerspoon?

Open von opened this issue 3 years ago • 31 comments

Once or week or so Hammerspoon seems to hang - it's unresponsive, I get a beachball when I hover over the menu bar icon, and if I open the Force Quit menu, it shows as unresponsive. My fix currently is to Force Quit and restart it.

Console output isn't showing anything irregular when its hung and I haven't been able to discern correlation with anything as a possible cause (it may be hung for a while before I notice). No doubt it could be something in my configuration, probably a race condition, but given it's not readily reproducible, turning off parts of my configuration to try and debug would seem to be a royal pain.

Anyone have any guidance for how to go about debugging this?

TIA.

von avatar Jul 26 '21 18:07 von

Can you share your config and/or the crash report when you force quit it? What version of Hammerspoon and macOS?

latenitefilms avatar Jul 26 '21 20:07 latenitefilms

Thanks for the response. I have my config in a private repo and it's rather large (>4000 lines total). if you are really serious about wanting to look through it, I can do a quick redaction of private content and post it. I do have some of my Spoons in Github.

I didn't know Force Quit created a Crash Report. I don't see any Crash Reports now when I look in the Console app but I just upgraded to 11.5 so I'm guessing they got overwritten. l'll look for one next time I run into the problem.

In terms of versions: Max OS X 11.5 and Hammerspoon 0.9.90 (6030).

Thanks again.

von avatar Jul 29 '21 00:07 von

It might also be instructive to see how much memory Hammerspoon is claiming when it's seeming hung... If it's particularly larger then usual, then it means we've got a memory leak somewhere (it wouldn't be the first time, and I know of at least one in the current release's hs.canvas module that I've posted a fix for, #2901, but it needs a little more testing before it's safe to land).

Open up the Activity Monitor and look at the memory usage for Hammerspoon... it's probably useful to check it every so often so you can get a feel for what your configuration usually looks like, then you have something to compare it to when it hangs.

asmagill avatar Jul 29 '21 01:07 asmagill

I too get Hammerspoon non-responsiveness every couple of days. I sometimes find that it relates to a single application in the background which isn't responding, even if it has no windows on the current screen. Once that app is force-quit, responsiveness typically returns to normal. emacs-mac seems to be a common culprit for me. Not sure if there are any ways to "give up" on an app HS is querying to avoid such across-the-board slow-downs (10's of seconds for grid moves, popping up the HS menu, etc.).

jdtsmith avatar Oct 20 '21 18:10 jdtsmith

I have the same, only Force Quit fixes the problem. I think I've had this problem since updating to macOS 12 Monterey.

Adding info for debugging purposes:

  • config
  • MacOS 12.01 (Monterey)
  • Hammerspoon 0.9.90
  • memory usage: 27 MB (seems reasonable)
  • CPU usage: 0%

My console gives "spindump": Hammerspoon [77828]: hang likely: not sampling due to conditions 0x400000000. I have no idea what that means.

nielsbom avatar Nov 21 '21 12:11 nielsbom

FYI: I've got a non-responsive Hammerspoon every couple of hours now.

nielsbom avatar Nov 24 '21 13:11 nielsbom

I've been looking into this problem as well and ultimately traced it down to hs.window.filter.defaultCurrentSpace:getWindows() calls which I was using in multiple places (often as part of an hs.chooser callback to make sure I was taking the corresponding action in the correct window). At some point this started happening (maybe macOS Monterey?) but it didn't occur to me as the cause for a while.

Don't have a workaround (other than not using it).

https://github.com/Hammerspoon/hammerspoon/issues/2943

hopefulwerewolf avatar Nov 29 '21 21:11 hopefulwerewolf

FYI, I don't explicitly use hs.window.filter.defaultCurrentSpace:getWindows() but do use the getWindows() method on hs.window.filter objects in various callbacks in such a way it could be the problem.

von avatar Nov 29 '21 22:11 von

I use allWindowsForSpace quite often. I've noticed that HS hangs often when there is a frozen app in the background. Killing that alleviates the freezes (often). Maybe getWindows + frozen or non-responsive app is the culprit?

jdtsmith avatar Nov 29 '21 22:11 jdtsmith

I tried to troubleshoot a little deeper on my end but didn't get really very far. The issue was happening specifically on accessing hs.window.filter.defaultCurrentSpace and not the getWindows() method.

It was oddly enough not happening with hs.window.filter.default (or was happening for a barely noticeable time rather than for multiple seconds).

I tried to dig a bit deeper but didn't really get super far. Something that was peculiar is that one way in which I use the function is only slow the first time, and then fast subsequently (so I have to reload hammerspoon to see the delayed behavior). In another use, it's slow every time.

I think this section is relevant: https://github.com/Hammerspoon/hammerspoon/blob/master/extensions/window/window.lua#L84-L89

Messing around with various windows that are open, calling application:allWindows() will cause a momentary delay. If you are looping through many applications and multiple have a long delay, this will add up. print(hs.inspect(hs.window._timed_allWindows())) can let you see this overall.

window.allWindows() will skip the entries in SKIP_APPS, but timed_allWindows() will not.

Furthermore, hs.window.filter can also call application:allWindows() directly, and keeps its own list of apps to skip with logic I can't follow as easily.

hopefulwerewolf avatar Nov 30 '21 03:11 hopefulwerewolf

I'm sometimes also noticing the unresponsive delay. From the code refs and comments on this page it follows that Hammerspoon will become unresponsive if one of the applications it queries with app:allWindows() is unresponsive. My usual suspects seem to be IntelliJ + WebStorm.

@asmagill What could be a way to circumvent this? Is there existing macOS functionality to query app responsiveness before attempting a risky app:allWindows()? Or perhaps doing this block-worthy work on a separate thread and return the results to HS asynchronously, so the rest of processing does not block?

jubr avatar Dec 07 '21 15:12 jubr

LOL, it's already available hs.application.isUnresponsive() @ https://github.com/Hammerspoon/hammerspoon/blob/master/extensions/application/libapplication.m#L252-L258

jubr avatar Dec 07 '21 15:12 jubr

I'm seeing a similar issue since moving to an M1 Mac about a year ago -- every few weeks I notice a trigger suddenly doesn't work, and when I look in Activity Monitor I see hammerspoon, highlighted in red "not responding". After I kill and restart everything is fine again. I've tried to "Sample Process" but don't understand the output.

I'll check Console.app next time and post here.

HS 0.9.93, MacOS 12.1

n8henrie avatar Jan 27 '22 21:01 n8henrie

Screen Shot 2022-02-04 at 16 30 10

No messages in console:

Screen Shot 2022-02-04 at 16 30 43

¯\_(ツ)_/¯

n8henrie avatar Feb 04 '22 23:02 n8henrie

Perhaps some kind of deadlock in JXA evaluation?

Screen Shot 2022-02-04 at 16 34 41

n8henrie avatar Feb 04 '22 23:02 n8henrie

After the above suggested it was a problem in the JXA evaluation, I think I figured it out.

I had launched MacVim with my hammerspoon keyboard shortcut:

hs.hotkey.bind(
  hyper,
  "V",
  nil,
  run_javascript("~/gists/f3abd106f6da2928b0b6a767a12f4b78/Open in MacVim.js")
)

where you can see that script here: https://gist.github.com/n8henrie/f3abd106f6da2928b0b6a767a12f4b78

I can't remember why I decided to use lua to call JXA to call a shell script...

EDIT: I think it's because I want the trigger to act on an existing selection in Finder, and I haven't figured out how else people are doing that

but regardless, Hammerspoon was apparently stuck waiting for that to all close out. As soon as I quit MacVim, all of the pending hammerspoon triggers that I'd called in the meantime all fired at once and it was responsive again.

So I don't know if that helps anyone else debug, but Activity Monitor -> hammerspoon (double click) -> sample -> display percent of thread was helpful for debugging in this case.

EDIT: And for my MacVim problem, here is a relevant issue: https://github.com/Hammerspoon/hammerspoon/issues/841#issuecomment-198421292, with the best solution I've come up with being os.execute.

n8henrie avatar Feb 05 '22 01:02 n8henrie

Major kudos to @n8henrie for debugging this, I'm experiencing the exact same issue when trying to open a specific webpage in Chrome (i'm assuming due to the way Chrome manages threads/processes/sandboxes):

    2568 Thread_240117   DispatchQueue_20: com.apple.root.user-interactive-qos.overcommit  (concurrent)
    + 2568 start_wqthread  (in libsystem_pthread.dylib) + 8  [0x19c04ce20]
    +   2568 _pthread_wqthread  (in libsystem_pthread.dylib) + 228  [0x19c04e0c4]
    +     2568 _dispatch_worker_thread2  (in libdispatch.dylib) + 164  [0x19bedd7c0]
    +       2568 _dispatch_root_queue_drain  (in libdispatch.dylib) + 684  [0x19bedd0b4]
    +         2568 _dispatch_client_callout  (in libdispatch.dylib) + 20  [0x19becb504]
    +           2568 _dispatch_call_block_and_release  (in libdispatch.dylib) + 32  [0x19bec99dc]
    +             2568 __45-[NSConcreteTask launchWithDictionary:error:]_block_invoke_2  (in Foundation) + 40  [0x19d0a5450]
    +               2568 __create_task_block_invoke  (in libtask.dylib) + 116  [0x112248234]
    +                 2568 _dispatch_sync_f_slow  (in libdispatch.dylib) + 144  [0x19beda934]
    +                   2568 __DISPATCH_WAIT_FOR_QUEUE__  (in libdispatch.dylib) + 368  [0x19bedad88]
    +                     2568 _dispatch_thread_event_wait_slow  (in libdispatch.dylib) + 56  [0x19becbca8]
    +                       2568 _dlock_wait  (in libdispatch.dylib) + 56  [0x19becbef4]
    +                         2568 __ulock_wait  (in libsystem_kernel.dylib) + 8  [0x19c014ba4]

FWIW, this only occurs on my Ventura machine, and not my Monterey machine (both M1)

pbdeuchler avatar Nov 01 '22 16:11 pbdeuchler

I can consistently reproduce this with just this lua snippet (copied from somewhere on SO):

function ChromeWithProfile()
  local profile = "Default"
  local url = "https://meet.google.com"
  local t = hs.task.new("/Applications/Google Chrome.app/contents/MacOS/Google Chrome", 
  nil,
  function() return false end,
  { "--profile-directory=" ..profile, url})
  t:start()
end
hotkey.bind(mash, 'D', ChromeWithProfile)

pbdeuchler avatar Nov 01 '22 16:11 pbdeuchler

Has anyone found a temporary solution to this? I'm also getting inconsistent hangs on Ventura (pretty sure the same task was working prior to upgrading yesterday)

Screenshot 2023-03-16 at 16 18 24

homerjam avatar Mar 16 '23 16:03 homerjam

I suspect there are probably several different things going on here, since we have a bunch of different reports going on in here. Apologies for not having interacted with this Issue before.

It's worth noting up-front that hs.applescript and hs.javascript (or hs.osascript directly) calls are always blocking, and if they go wrong or get stuck, that can cause these "Not Responsing" situations. hs.task should not be blocking though, so I'm a little surprised about the Chrome invocation causing Hammerspoon to lock up.

cmsj avatar Mar 16 '23 16:03 cmsj

@n8henrie debugged it in his linked issue, it's a hang when the process is backgrounded or forked. IIRC hammerspoon expects a return or a handle, and never gets one, and since these calls are blocking it just hangs

pbdeuchler avatar Mar 16 '23 16:03 pbdeuchler

FWIW I'm using hs.task to run sh scripts (run node server, open browser windows), and then hs.window and hs.screen to position said windows. There's also hs.timer to deal with async/scheduling of tasks.

I was working locally on Monteray and testing remotely on Ventura previously - I had issues on Ventura which I put down to something else. However since I upgraded to Ventura locally I have the issues on both machines.

homerjam avatar Mar 16 '23 16:03 homerjam

@pbdeuchler I think that was a usage of hs.execute() or os.execute() which are also blocking.

For launching browsers, I would recommend a pattern like this (which is a function I use with the URLDispatcher spoon):

function open_work_url(url)
    local browserPath = "/Applications/Microsoft\\ Edge/Contents/MacOS/Microsoft\\ Edge"
    local browserName = "Microsoft Edge"
    local browserProfile = "Work"
    local browserArgs = "--args --profile-directory='"..browserProfile.."'"

    pos, _ = string.find(url, "https://meet.google.com/", 1)
    if pos == 1 then
        browserArgs = browserArgs.." --new-window"
    end

    local execute = "/usr/bin/open -na '"..browserName.."' --args "..browserArgs.." '".. url .."'"

    hs.execute(execute)
end

using /usr/bin/open means the OS itself takes responsibilty for doing the launching and it returns very quickly.

cmsj avatar Mar 16 '23 16:03 cmsj

@n8henrie debugged it in his linked issue, it's a hang when the process is backgrounded or forked. IIRC hammerspoon expects a return or a handle, and never gets one, and since these calls are blocking it just hangs

Ah ok so a quick search suggests Ventura has brought new transparency to background tasks (similar to how login items work). It appears that Hammerspoon isn't in the list of applications permitted to work in the background on my machine, however it's not clear how to add an application here either (there is a + plus icon for login items)

homerjam avatar Mar 16 '23 16:03 homerjam

@homerjam is there a specific bit of your config that is causing Hammerspoon to stop responding? I don't think that is correct (permission being required for background tasks).

cmsj avatar Mar 16 '23 16:03 cmsj

@homerjam is there a specific bit of your config that is causing Hammerspoon to stop responding? I don't think that is correct (permission being required for background tasks).

Not as far as I can tell, I have tried endless combinations and running each task in isolation and there is nothing that remains consistent.

Edit: actually using execute to open the browser seems to have resolved my problem, thanks!

homerjam avatar Mar 16 '23 16:03 homerjam

I can't remember why I decided to use lua to call JXA to call a shell script...

EDIT: I think it's because I want the trigger to act on an existing selection in Finder, and I haven't figured out how else people are doing that

I randomly figured this out recently.

I have a shell script wrapped in a .app that uses applescript to get the selection but it's a bit janky, going to see if using hammerspoon works a bit better.

I've got as far as listing the paths in the console:

local ax = require("hs.axuielement")

local function printSelectedFileURLs()
  local selectedChildren = ax.applicationElement("Finder").AXFocusedUIElement.AXSelectedChildren

  for _, child in ipairs(selectedChildren) do
    for _, sub in ipairs(child) do
      local url = sub:attributeValue("AXURL")
      if url and url.filePath then
        print(url.filePath)
      end
    end
  end
end

hs.hotkey.bind(hyper, 'm', printSelectedFileURLs)

It seems responsive even with quite a few files selected. Not sure if it's possible to remove that inner loop or not, tried but I can't figure it out.

PhrantiK avatar May 25 '23 09:05 PhrantiK