hammerspoon
hammerspoon copied to clipboard
Hammerspoon
Print statements hanging Hammerspoon and triggering memory leak
Hello, after I've upgraded from Sonoma 14.0 to 14.1, my script stops responding a few times a day. Hammerspoon becomes unresponsive, the console becomes blank, and the memory starts increasing indefinitely to several GB.
I've worked around the issue by removing all print statements, and now it no longer crashes, but I spent some time anyway trying to isolate the reason.
This snippet should reproduce the issue when pasted on the console:
hs.console.setConsole("")
local i = 1
local length = 0
T = hs.timer.doEvery(0.005, function ()
print(i .. ": " .. string.rep(".", length))
length = (length + 1) % 40
i = i + 1
end)
On an M1 and on an Intel (both Sonoma 14.1), it hangs after 2000-3000 iterations.
Interestingly, it doesn't happen if all the strings after some point are the same length, such as with just print(i). Then it crashes a few numbers after 10000 (because i changed from 4 to 5 digits). That holds true even if i starts at -1000 or -5000, it would still crash a bit after 10000.
It also doesn't happen when disabling the history limit with hs.console.maxOutputHistory(0) so it could be related to the characters being deleted on #3400.
I've been having the same issue. Tried running your code for a couple minutes, and indeed HS hung and its memory usage suddenly shot up >1GB and rising. Looks like a CPU issue. Here's the start of the issue per the console:
default 09:26:03.812424-0800 kernel process Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds
default 09:26:03.816067-0800 symptomsd Received CPU usage trigger:
Hammerspoon[45528] () used 90.00s of CPU over 110.10 seconds (averaging 81%), violating a CPU usage limit of 90.00s over 180 seconds.
default 09:26:03.819713-0800 symptomsd RESOURCE_NOTIFY trigger for Hammerspoon [45528] (90000000041 nanoseconds of CPU usage over 110.00s seconds, violating limit of 90000000000 nanoseconds of CPU usage over 180.00s seconds)
default 09:26:04.182218-0800 spindump Saved cpu_resource.diag report for Hammerspoon version 0.9.100 to Hammerspoon_2023-11-29-092603_Justins-MacBook-Air.cpu_resource.diag
default 09:26:12.071459-0800 spindump Hammerspoon [45528]: hang likely: not sampling due to conditions 0x400000000
default 09:26:13.204859-0800 Activity Monitor Hammerspoon [45528] force quit
default 09:26:13.226929-0800 runningboardd Invalidating assertion 415-403-34710 (target:[app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]) from originator [osservice<com.apple.WindowServer(88)>:403]
default 09:26:13.219631-0800 WindowManager Connection invalidated | (45528) Hammerspoon
default 09:26:13.227031-0800 runningboardd XPC connection invalidated: [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default 09:26:13.227526-0800 runningboardd Invalidating assertion 415-403-34709 (target:[app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]) from originator [osservice<com.apple.WindowServer(88)>:403]
default 09:26:13.425726-0800 runningboardd [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528] termination reported by launchd (2, 15, 15)
default 09:26:13.425786-0800 runningboardd Removing process: [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default 09:26:13.426033-0800 runningboardd Removed last relative-start-date-defining assertion for process app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>
default 09:26:13.426142-0800 runningboardd Removing launch job for: [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default 09:26:13.426609-0800 runningboardd Removed job for [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default 09:26:13.430299-0800 runningboardd Removing assertions for terminated process: [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default 09:26:13.437990-0800 runningboardd Calculated state for app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>: none (role: UserInteractiveNonFocal)
default 09:26:13.438972-0800 runningboardd Calculated state for app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>: none (role: None)
default 09:26:13.439666-0800 runningboardd Calculated state for app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>: none (role: None)
default 09:26:13.446367-0800 gamepolicyd Received state update for 45528 (app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>, none-NotVisible
default 09:26:13.446744-0800 launchservicesd Hit the server for a process handle 10f8f88a0000b1d8 that resolved to: [app<application.org.hammerspoon.Hammerspoon.98212600.98212606(501)>:45528]
default 09:26:13.454308-0800 loginwindow -[PersistentAppsSupport applicationQuit:] | for app:Hammerspoon, _appTrackingState = 2
default 09:26:13.454343-0800 loginwindow -[PersistentAppsSupport applicationQuit:] | App: Hammerspoon, quit, updating active tracking timer
default 09:26:15.920463-0800 spindump [45528]: Displaying hang dialog for Hammerspoon
default 09:26:15.920603-0800 spindump_agent Presenting hang dialog to user for app Hammerspoon
default 09:26:17.674204-0800 spindump_agent User chose (Ignore) for app Hammerspoon
default 09:26:18.456521-0800 loginwindow -[PersistentAppsSupport saveLogoutPersistentState:finalSnapshot:] | previouslyRunningApps: (
{
BackgroundState = 0;
BundleID = "com.apple.console";
Hide = 0;
Path = "/System/Applications/Utilities/Console.app";
},
{
BackgroundState = 2;
BundleID = "com.google.chrome";
Hide = 0;
Path = "/Applications/Google Chrome.app";
},
{
BackgroundState = 2;
BundleID = "com.apple.activitymonitor";
Hide = 0;
Path = "/System/Applications/Utilities/Activity Monitor.app";
},
{
BackgroundState = 3;
BundleID = "org.hammerspoon.hammerspoon";
Hide = 0;
Path = "/Applications/Hammerspoon.app";
},
{
BackgroundState = 2;
BundleID = "com.microsoft.vscode";
Hide = 0;
Path = "/Applications/Visual Studio Code.app";
},
{
BackgroundState = 2;
BundleID = "com.googlecode.iterm2";
Hide = 0;
Path = "/Applications/iTerm.app";
},
{
BackgroundState = 2;
BundleID = "com.apple.systempreferences";
Hide = 0;
Path = "/System/Applications/System Settings.app";
},
{
BackgroundState = 2;
BundleID = "com.apple.textedit";
Hide = 0;
Path = "/System/Applications/TextEdit.app";
},
{
BackgroundState = 2;
BundleID = "com.apple.finder";
Hide = 0;
Path = "/System/Library/CoreServices/Finder.app";
}
)
default 09:27:29.470602-0800 Console update collaboration items for activityItems:(
"default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
default 09:27:29.470659-0800 Console request collaboration items for activity items:(
"default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
default 09:28:28.672517-0800 Console update collaboration items for activityItems:(
"default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
default 09:28:28.672555-0800 Console request collaboration items for activity items:(
"default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
default 09:28:53.160623-0800 Console update collaboration items for activityItems:(
"default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
default 09:28:53.160674-0800 Console request collaboration items for activity items:(
"default\t09:26:03.812424-0800\tkernel\tprocess Hammerspoon[45528] thread 831168 caught burning CPU! It used more than 50% CPU over 180 seconds\n"
)
Also have been running into this issue, my hotkeys suddenly stop working and memory usage starts increasing rapidly (usually I catch it at ~10-50 GB but just now I only noticed it at several hundred GB).
I only have one print but I guess it's triggered on every focus change, I'll try removing it. Though HS also prints stuff every time hotkeys get enabled and disabled, which also happens quite often for me, hopefully that doesn't matter, since hs.console.maxConsoleHistory(0) doesn't seem like a great solution either.
Can confirm the issue here.
Indeed if Toggling hotkey use the same function as print, I don't really have any workaround for that. @benediktwerner I think you meant hs.console.maxOutputHistory(0). If set to 0, the output will be normal. Minimum required is 1. Which may trigger the issue too in the end.
For now I'm trying hs.console.maxOutputHistory(1), w/ a custom code to rewrite console to file
hammerspoonLogFile = assert(io.open('hammerspoon-console.log','a'))
hammerspoonLogFile:setvbuf("line")
-- Override Hammerspoon's print with print that logs to file, not just HS console
-- See print() definition in https://github.com/Hammerspoon/hammerspoon/blob/master/extensions/_coresetup/init.lua
local old_print, tostring = print, tostring
local tconcat, pack = table.concat, table.pack
print = function(...)
local vals = pack(...)
for k = 1, vals.n do
vals[k] = tostring(vals[k])
end
local l = tconcat(vals, "\t")
hammerspoonLogFile:write(l, '\n')
return old_print(l)
end
Though HS also prints stuff every time hotkeys get enabled and disabled, which also happens quite often for me
Indeed if Toggling hotkey use the same function as print, I don't really have any workaround for that.
It's not documented[^notdoc] (Edit: yet - see comments below), but there's actually an hs.hotkey.setLogLevel function that can control the enable/disable messages for hotkeys. (It's actually the setLogLevel method of the hs.logger instance used by hs.hotkey internally. getLogLevel is exposed too.) Enable/disable messages are logged at info level[^modal], so setting the logger's level to nothing, error, or warning should hide them.
(Also, by default, entering/exiting an hs.hotkey.modal is silent - as long as none of the hotkeys conflict with ones that were already enabled before the modal was entered.)
[^notdoc]: ~~Or rather, it is documented in the source code for hs.hotkey, but it doesn't seem to be making it into the rendered documentation for some reason.~~ Edit: Apparently the docs just got added, and haven't made it into a release yet. The specifics of what gets logged at what level really aren't documented, though.
[^modal]: Or debug if the hotkey is being toggled as part of a modal.
Though HS also prints stuff every time hotkeys get enabled and disabled, which also happens quite often for me
Indeed if Toggling hotkey use the same function as print, I don't really have any workaround for that.
It's not documented1, but there's actually an
hs.hotkey.setLogLevelfunction that can control the enable/disable messages for hotkeys. (It's actually thesetLogLevelmethod of thehs.loggerinstance used byhs.hotkeyinternally.getLogLevelis exposed too.) Enable/disable messages are logged atinfolevel2, so setting the logger's level tonothing,error, orwarningshould hide them.(Also, by default, entering/exiting an
hs.hotkey.modalis silent - as long as none of the hotkeys conflict with ones that were already enabled before the modal was entered.)Footnotes
- Or rather, it is documented in the source code for
hs.hotkey, but it doesn't seem to be making it into the rendered documentation for some reason. The specifics of what gets logged at what level really aren't documented, though. ↩- Or
debugif the hotkey is being toggled as part of a modal. ↩
Thanks, hs.hotkey.setLogLevel("warning") indeed works to hide hotkey message set at launch, and also for those set disabled / enabled dynamically.
As for modal, indeed no message is shown.
Whoops. I just realized how recent that commit I linked was - it's not actually in a release yet, so of course it's not showing up in the documentation.
Thank you for this report, I've run into the same "mysterious" freezing issue for a while, although I did not really change my configuration. I've removed a lot of logging from my codebase and hopefully, this should lessen the issue.
FWIW I had the same issue, reduced logging to almost nothing and at least it's not crashing anymore. Would still like to be able to get my logging back though. ;]
Though HS also prints stuff every time hotkeys get enabled and disabled, which also happens quite often for me, hopefully that doesn't matter, since
hs.console.maxConsoleHistory(0)doesn't seem like a great solution either.
I have created a helper to disable the logging for some hotkeys: https://github.com/muescha/dot_hammerspoon/blob/master/Helpers/HotkeySilence.lua#L17-L22
usage in: https://github.com/muescha/dot_hammerspoon/blob/master/Helpers/HotkeyBindSafe.lua#L27-L29
https://github.com/muescha/dot_hammerspoon/blob/master/Helpers/SendKeysOnlyInApp.lua#L123-L125
Same issue for me! and this seems only happens on apple silicon not intel based mac, any suggestions up to now?
FWIW this is happening on my Intel Mac. I did manage to mitigate it by reducing the print/logging statements to almost nothing.
So the behaviour here is really interesting. With the default console history length of 100,000 characters, I can also reliably repeat the hang using @gab-john 's test snippet, after about 2100 iterations. Dropping the history length to 50,000 characters raises the hang point to about 38,000 iterations, by which point Hammerspoon is using 20GB of RAM.
I think it's pretty clear that the current methodology for truncating scrollback is a complete disaster that will eventually fail at any length limit (although it looks like the scaling is non-linear, so a limit like 5,000 ought to hold crashes off for a very long time) because something is leaking.
I've quickly profiled a debug build and it looks like the majority of the RAM allocations are coming from text related classes in AppKit.
So, this is either a generic bug in AppKit that eventually an infinitely growing NSTextView will just hang, or there is something more subtle going on. One hypothesis I had was that because we just delete characters off the front of the underlying NSTextStorage, we would be confusing the fact that they were added as NSAttributedStrings, but I don't think that can be it because the hang doesn't seem to be happening very close to where that happens.
I'll keep poking at this and see what I can come up with.
Ok, I've restructured the way text is written to the console, and it will now be batched up and only actually committed to the NSTextView every 0.2 seconds. I've also changed some settings on the NSTextView to turn off a lot of the fancy things that make no sense for a log viewer (things like spell checking) and while I'm not super happy with the RAM usage, the situation overall appears to be dramatically improved.
After 20,000 iterations of the snippet, with the default 100,000 character history limit, Hammerspoon is still running fine, and RAM usage has "only" grown to 1.9GB. I suspect there is still a hang lurking out there in the future, but it should now be far less likely to be hit in any reasonable session. I'll push the code up shortly and I'm hoping to get a release out in the next couple of days.
Thanks all for your contributions here, and apologies it's taken so long to address!