Print statements hanging Hammerspoon and triggering memory leak about hammerspoon

[jkroes]

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"
)

[benediktwerner]

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.

[Write]

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

[Rhys-T]

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¹ (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², 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.)

Footnotes

1. 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. ↩

2. Or debug if the hotkey is being toggled as part of a modal. ↩

[Write]

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.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 level2, 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.)

Footnotes

1. 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. ↩
2. Or debug if 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.

[latenitefilms]

Related:

Add setLogLevel documentation for each extension #2248

[Rhys-T]

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.