[bug] Hammerspoon (and forked child processes) can't see files in /Applications when launched as a Login Item

[dljsjr]

Environment

OS: macOS Sonoma (encountered on 14.1.x, 14.2.x, and 14.3.x)
Arch: Intel
Hammerspoon Version: Version 0.9.100 (6815)

Bug Report

I recently developed a Spoon for myself and I noticed that sometimes it hangs on loading of my config. Activity Monitor shows very high CPU usage and very high virtual memory usage in this situation. I saw a virtual RAM usage of over 40 GB on a cold boot of my MBP with ~100% CPU.

I dug in to Console.app and found a Diagnostic Report that captured the heaviest stack, and it seems to be related to hs.application.applicationsForBundleID:

Captured Heavy Stack

Heaviest stack for the target process:
  83  start + 1942 (dyld + 25510) [0x7ff814dd93a6]
  83  ??? (AppKit + 15888) [0x7ff818810e10]
  83  ??? (AppKit + 196127) [0x7ff81883ce1f]
  83  ??? (AppKit + 5181663) [0x7ff818cfe0df]
  83  ??? (AppKit + 9636755) [0x7ff81913db93]
  83  ??? (HIToolbox + 125001) [0x7ff81facb849]
  83  ??? (HIToolbox + 39759) [0x7ff81fab6b4f]
  83  ??? (HIToolbox + 42755) [0x7ff81fab7703]
  83  hotkey_callback + 183 (libhotkey.dylib + 9984) [0x111761700]
  83  trigger_hotkey_callback + 322 (libhotkey.dylib + 9183) [0x1117613df]
  83  -[LuaSkin protectedCallAndError:nargs:nresults:] + 55 (LuaSkin + 25303) [0x10e3272d7]
  83  -[LuaSkin protectedCallAndTraceback:nresults:] + 251 (LuaSkin + 25136) [0x10e327230]
  83  lua_pcallk + 383 (LuaSkin + 179101) [0x10e34cb9d]
  83  luaD_pcall + 92 (LuaSkin + 162913) [0x10e348c61]
  83  luai_objcttry + 28 (LuaSkin + 70804) [0x10e332494]
  83  luaD_callnoyield + 84 (LuaSkin + 161497) [0x10e3486d9]
  82  luaV_execute + 18005 (LuaSkin + 121325) [0x10e33e9ed]
  82  luaD_precall + 303 (LuaSkin + 161207) [0x10e3485b7]
  82  precallC + 141 (LuaSkin + 160721) [0x10e3483d1]
  35  application_applicationsForBundleID + 160 (libapplication.dylib + 17908) [0x1183c15f4]
  32  -[LuaSkin pushNSObject:withOptions:] + 110 (LuaSkin + 32859) [0x10e32905b]
  20  -[LuaSkin pushNSObject:withOptions:alreadySeenObjects:] + 580 (LuaSkin + 41679) [0x10e32b2cf]
  11  ??? (Foundation + 12622) [0x7ff81617c14e]
  9   look_up_class + 70 (libobjc.A.dylib + 39069) [0x7ff814d9a89d]
  9   getClassExceptSomeSwift(char const*) + 15 (libobjc.A.dylib + 39448) [0x7ff814d9aa18]
  6   getClass_impl(char const*) + 151 (libobjc.A.dylib + 39666) [0x7ff814d9aaf2]
  5   dyld4::APIs::_dyld_for_each_objc_class(char const*, void (void*, bool, bool*) block_pointer) + 174 (dyld + 240696) [0x7ff814e0dc38]
  3   objc::ObjectHashTable::forEachObject(char const*, void (unsigned long long, unsigned short, bool&) block_pointer) const + 25 (dyld + 252749) [0x7ff814e10b4d]
  1   objc::StringHashTable::tryGetIndex(char const*) const + 114 (dyld + 260618) [0x7ff814e12a0a]

Here's the entire diagnostic report: Hammerspoon_2024-02-07-092250_marvin.cpu_resource.diag.zip

The Spoon in question (and the issue on the Spoon for tracking this): dljsjr/Visor.spoon#1

[dljsjr]

So I've noticed that this happens the very first time this function (hs.application.applicationsForBundleID) is called after a macOS boot. Hammerspoon will hang, I'll killall Hammerspoon and relaunch, and it'll work well until my next reboot. After that, it always gums up at this call the first time.

[dljsjr]

I refactored my Spoon over the weekend to avoid the hang and I think I have an idea of what's causing it.

It seems that when Hammerspoon is a Login Item, it's coming up in such a way that it's not able to find app bundles in /Applications until it's been restarted. My spoon performs some shell-out commands to a CLI that's part of an App Bundle, and it reports no such file or directory if I introspect it:

2024-02-12 09:24:49: [DEBUG] [Visor.spoon]: Executing kitty cmd "1>/Users/dougstephen/.hammerspoon/Spoons/Visor.spoon/kitty/kitty_daemon.out 2>/Users/dougstephen/.hammerspoon/Spoons/Visor.spoon/kitty/kitty_daemon.err nohup kitty -d $HOME -1 --instance-group KITTY_HOTKEY_WINDOW -T KITTY_HOTKEY_WINDOW --listen-on unix:/Users/dougstephen/.hammerspoon/Spoons/Visor.spoon/kitty/socket -c /Users/dougstephen/.hammerspoon/Spoons/Visor.spoon/kitty/visor_window.conf false &"
2024-02-12 09:24:49: [DEBUG] [Visor.spoon]: status: nil, pid: 
2024-02-12 09:24:49: [ERROR] [Visor.spoon]:       Could not locate PID of Kitty daemon; checking output files.
      stdout: 
      stderr: nohup: kitty: No such file or directory

However, shelling out manually from a terminal application shows no issues:

$ 1>/Users/dougstephen/.hammerspoon/Spoons/Visor.spoon/kitty/kitty_daemon.out 2>/Users/dougstephen/.hammerspoon/Spoons/Visor.spoon/kitty/kitty_daemon.err nohup kitty -d $HOME -1 --instance-group KITTY_HOTKEY_WINDOW -T KITTY_HOTKEY_WINDOW --listen-on unix:/Users/dougstephen/.hammerspoon/Spoons/Visor.spoon/kitty/socket -c /Users/dougstephen/.hammerspoon/Spoons/Visor.spoon/kitty/visor_window.conf false &
[1] 7337

$ ps aux | grep kitty         
dougstephen       7391   0.0  0.0 33728048    660 s002  R+    9:28AM   0:00.00 grep --color=auto --exclude-dir=.bzr --exclude-dir=CVS --exclude-dir=.git --exclude-dir=.hg --exclude-dir=.svn --exclude-dir=.idea --exclude-dir=.tox kitty
dougstephen       7337   0.0  0.2 34929352  80896 s002  SN    9:28AM   0:00.72 /Applications/kitty.app/Contents/MacOS/kitty -d /Users/dougstephen -1 --instance-group KITTY_HOTKEY_WINDOW -T KITTY_HOTKEY_WINDOW --listen-on unix:/Users/dougstephen/.hammerspoon/Spoons/Visor.spoon/kitty/socket -c /Users/dougstephen/.hammerspoon/Spoons/Visor.spoon/kitty/visor_window.conf false
root              7095   0.0  0.0 34291264   4008 s000  Ss    9:27AM   0:00.02 /usr/bin/login -f -l -p dougstephen /Applications/kitty.app/Contents/MacOS/kitten run-shell --shell /bin/zsh --shell-integration no-cursor --cwd=/Users/dougstephen
dougstephen       7094   0.0  0.3 35969248  97904   ??  S     9:27AM   0:01.62 /Applications/kitty.app/Contents/MacOS/kitty

And then after quitting and re-launching Hammerspoon, everything works fine.

[Rhys-T]

Hmm… It looks to me like that error message is actually nohup complaining that it can't find the kitty command in any directory in the search path. For some reason nohup uses No such file or directory instead of command not found to report that:

> hs.execute [[nohup asfhklsajf 2>&1]]
nohup: asfhklsajf: No such file or directory
	nil	exit	127

I'm not sure where you have the kitty command installed (is it the same as the .../MacOS/kitty executable of the app itself?), or how you're adding that to $PATH, but I kind of suspect that Hammerspoon is getting launched before $PATH has been updated and just doesn't know where to look for kitty, rather than not having access to that part of the filesystem - which would probably make it a separate issue from the applicationsForBundleID problem.

Just to make sure, though, next time Hammerspoon starts as a login item and is failing to run the kitty command, can you try running:

print(hs.execute [[ls /Applications]])
-- and/or
print('[[[')
for file in hs.fs.dir('/Applications') do
	print('\t' .. file)
end
print(']]]')

and see if it can see the apps that way?

[dljsjr]

@Rhys-T I'll try that and get back to you with the output!

As a few more points of clarification:

It's expecting a kitty element in the $PATH, which on my system is at /usr/local/bin/kitty, which is a symlink to a wrapper script in my Homebrew Cellar that exec's the CLI in the .app Bundle. However, it also fails if I modify it to use an absolute path.

Additionally, it was failing before the nohup when I was still using hs.application.applicationsForBundleID in the Spoon by spinning forever.

[dljsjr]

@Rhys-T The files are there. The more I spend time with it, the more I'm starting to think that the issue is related to the environment. I'm going to go out on a limb and guess that macOS Login Items don't inherit the user's typical login environment and things like their $PATH? That would probably cause some of what I'm seeing, as I use wrapper scripts in /usr/local/bin and $HOME/.local/bin for some of the functionality.

This hunch is further corroborated by the fact that if I use hs.relaunch() from the console instead of quitting the app and launching it explicitly, the issue persists.

[asmagill]

Hammerspoon (in fact all MacOS application bundles) do not inherit any path or environment variables set by the traditional shell init scripts.

I haven't read the whole thread (I will tomorrow, but this caught my eye right before heading off to bed), but since I have noticed you're using hs.execute, check out the second argument to the command at http://www.hammerspoon.org/docs/hs.html#execute -- it's a boolean specifically added to force running the command through your default shell so that it will inherit such.

Try doing hs.execute("... whatever ...", true) and see if that makes a difference.

[dljsjr]

Hammerspoon (in fact all MacOS application bundles) do not inherit any path or environment variables set by the traditional shell init scripts.

I know it doesn't take the interactive login stuff like ~/.zshrc. It seems like there's a difference between login items vs. other environments, though. I'm wondering if login items don't inherit the higher level profile stuff that a normal login shell would take. Because as soon as I kill Hammerspoon then relaunch it via Raycast or Finder, everything is well-behaved.

Forcing it to inherit the user environment might work. I'd like to find a way to make it work as a login item the same way it works otherwise if possible, though, because of this note in the docs:

Setting with_user_env to true does incur noticeable overhead, so it should only be used if necessary (to set the path or other environment variables).

I'll try it out though as it's a good baseline I could use to start from if it does fix things.

[dljsjr]

@Rhys-T @asmagill I added the following to my init.lua:

print(
  string.format(
    "\n'$0': %s\n'$SHELL': %s\nShell options: %s\nShell env: %s\n",
    hs.execute([[echo $0]]),
    hs.execute([[echo $SHELL]]),
    hs.execute([[echo $-]]),
    hs.execute([[( setopt posixbuiltin; set; )]])
  )
)

I've made a zip with the two outputs. The shell options are the same, but for whatever reason, the $PATH value is in fact different for child procs of the login item vs. the manually launched app:

shell_metadata.zip

[dljsjr]

One last update: I changed all the shellouts to use absolute paths and I no longer see the issue with nohup. But in the locations where I swapped app lookup via bundleId (which was hanging) to use app lookup via PID, I now get an error from LuaSkin saying it can't find the app for the given PID. This seems like it's a cousin to the issue where looking the app up via Bundle ID was hanging.

[dljsjr]

So I did a much more thorough audit of my setup, and after making sure I made everything absolute paths in both the spoon and my wrapper scripts, the issue has gone away.

Meaning: it seems that the other stuff related to app bundles was a red herring. The larger issue was the one in my previous comment, which is that the /usr/local/bin element is not present in the $PATH for login items on my machine. I'm still trying to figure out why that is; /usr/local/bin is in /etc/paths. This likely isn't an issue with Hammerspoon itself, unless there's something the Hammerspoon launch config is doing to establish its path. So this can probably be closed.