Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Alt-tab showing errors in system console launchd.log #2225

Closed
burdo3417 opened this issue Dec 25, 2022 · 16 comments
Closed

Alt-tab showing errors in system console launchd.log #2225

burdo3417 opened this issue Dec 25, 2022 · 16 comments
Labels
bug Something isn't working

Comments

@burdo3417
Copy link

burdo3417 commented Dec 25, 2022

The same error it's shown in the console log every milisecond.

I'm not sure what is it.

I'm having a bit of high CPU usage, not sure if this is the cause.

Screenshot 2022-12-25 at 16 42 48

  • AltTab version: 6.51.0
  • macOS version: 13.1
  • System: Macbook Pro M1 Pro (Apple Silicon)
@burdo3417 burdo3417 added the bug Something isn't working label Dec 25, 2022
@lwouis
Copy link
Owner

lwouis commented Dec 26, 2022

Hi,

Looks like AltTab is trying to lookup some process in the OS called com.apple.axserver. AltTab has to listen to many processes on the OS so it can be notified when they spawn windows. Some services come and go, and here it looks like it's gone and AltTab is trying to listen still.

I'm not sure anything can be done. There is normal timeout to most retries in AltTab, so this shouldn't happen for a long period. It should probably also not impact your CPU much. You can check the Activity Monitor app to confirm AltTab's CPU usage.

Closing this as I don't see what could possibly be done here. The OS is logging this, not AltTab. AltTab is listening to processes as an essential part of windows tracking.

@lwouis lwouis closed this as completed Dec 26, 2022
@siikamiika
Copy link

siikamiika commented Jan 14, 2023

@burdo3417 are you using Firefox? For me the PID of the processes with name = com.apple.axserver in the log match the Firefox plugin container and the PID changes over time:

/Applications/Firefox.app/Contents/MacOS/plugin-container.app/Contents/MacOS/plugin-container

The actual bundle ID for that app is org.mozilla.plugincontainer in /Applications/Firefox.app/Contents/MacOS/plugin-container.app/Contents/Info.plist.

It didn't seem to help when I tried to blacklist both com.apple.axserver and org.mozilla.plugincontainer, or even the entire org.mozilla.firefox.


I guess these are related #1481 #1484 (cc @metacodes)

@siikamiika
Copy link

siikamiika commented Jan 14, 2023

I was able to silence this by not starting observeEvents for org.mozilla.plugincontainer but I don't know why it is problematic for AltTab. Firefox windows are still visible in AltTab even with the change.

diff --git a/src/logic/Application.swift b/src/logic/Application.swift
index 20733a3..56ba3b3 100644
--- a/src/logic/Application.swift
+++ b/src/logic/Application.swift
@@ -55,7 +55,9 @@ class Application: NSObject {
             axUiElement = AXUIElementCreateApplication(pid)
             AXObserverCreate(pid, axObserverCallback, &axObserver)
             debugPrint("Adding app", pid ?? "nil", runningApplication.bundleIdentifier ?? "nil")
-            observeEvents()
+            if (runningApplication.bundleIdentifier != "org.mozilla.plugincontainer") {
+                observeEvents()
+            }
         }
     }

edit: I can still see the error sometimes, but now the PID being logged is no longer running unlike with org.mozilla.plugincontainer. Idea: could this retry loop be exited immediately if there is no process for the PID of the Application?

@burdo3417
Copy link
Author

I am using Firefox.

Where do you make these changes?

@siikamiika
Copy link

This function, then compiled a debug build in Xcode. Had to delete the existing permissions for AltTab to get the debug build working, probably because of code signing differences compared to the production build

func observeEventsIfEligible() {
if runningApplication.activationPolicy != .prohibited && axUiElement == nil {
axUiElement = AXUIElementCreateApplication(pid)
AXObserverCreate(pid, axObserverCallback, &axObserver)
debugPrint("Adding app", pid ?? "nil", runningApplication.bundleIdentifier ?? "nil")
observeEvents()
}
}

@lwouis
Copy link
Owner

lwouis commented Jan 14, 2023

@siikamiika

Idea: could this retry loop be exited immediately if there is no process for the PID of the Application?

The process has a PID every time it's retrying:

Screen.Recording.2023-01-14.at.21.02.45.mov

Eventually it stops retrying, because there is a timeout (2min). The reason we retry is because some process are spawned, and they won't let AltTab subscribe to their events right away. They may be showing the user a splash screen as they load lots of important infrastructure (e.g. Gimp, Photoshop). We have to retry until it works, as there is no other way to know when the app is ready. The .isFinishedLaunching attribute is only telling that the macOS process is done launching, not that the app is actually ready. That part is business logic that's unique to each app. Similar to how each web server typically has their own way of notifying the user that they are ready for clients. Retrying until it works, or until a reasonable amount of time has passed (2min) is the only way. It's a trade-off between waiting too long and wasting CPU, and waiting not long enough, and missing to observe apps that are slow to get ready, and then their windows won't appear in AltTab.

Furthermore, the retries are only every 250ms, so it's really not going to make the CPU go crazy.

I think the main issue here is that Firefox spawns multiple of these buggy plugincontainer processes, and each of them never answers to the AX subscribe call, so it makes AltTab retries for maybe 10 processes, 4 times a second, which is 40 times a second. That drives my CPU to 3-4% on my M2 macbook.

We could blacklist that process since it's very specific to Firefox. Or Mozilla could fix it. That would work too.

@burdo3417
Copy link
Author

burdo3417 commented Jan 14, 2023

Blacklist it please!
The battery consumption is significant

@siikamiika
Copy link

@lwouis Thank you for the reply!

The process has a PID every time it's retrying:

Yes, you're seeing the same thing as me with plugincontainer, that's good to confirm. I agree that it makes sense to try again until the process responds as long as the process is running, but I'm not very familiar with macOS programming in general.

Anyway, I was a bit unclear what I meant by my idea. I meant processes that are not plugincontainer but show up in the logs. However, after some testing this doesn't seem to be a problem. I ran the following script and was able to capture the name of the process that still caused com.apple.axserver logging after ignoring plugincontainer. What I expected to be a 2 minute log spam stopped as soon as it started. System Settings does not immediately reply to AltTab and I always quit it before checking the logs, so I initially expected that the logs came after terminating the process, which is not the case below:

import psutil
import time
import datetime

procs = {}
while True:
    ts = datetime.datetime.now().isoformat()
    for proc in psutil.process_iter():
        if proc.pid not in procs:
            procs[proc.pid] = proc
            print(ts, proc)
    for proc in list(procs.values()):
        if not proc.is_running():
            print(ts, proc)
            del procs[proc.pid]

    time.sleep(0.5)
3802:2023-01-16 23:25:44.096733 (gui/501 [100018]) <Notice>: could not find endpoint in pid namespace: pid = 55277, name = com.apple.axserver
3804:2023-01-16 23:25:44.096746 (system) <Notice>: could not find endpoint in pid namespace: pid = 55277, name = com.apple.axserver
3805:2023-01-16 23:25:44.096754 (gui/501 [100018]) <Warning>: failed lookup: name = com.apple.axserver, handle = 55277, flags = 0x3, requestor = AltTab[53090], error = 3: No such process
2023-01-16T23:25:44.520371 psutil.Process(pid=55277, name='System Settings', status='running', started='23:25:44')
...
2023-01-16T23:25:48.261116 psutil.Process(pid=55277, name='System Settings', status='terminated', started='23:25:44')

I was personally more concerned about SSD durability than CPU usage when I found this, and was going through the entire file system to find files that are being written to constantly. I agree that 250 ms is a reasonable retry interval if the plugincontainer noise is silenced.

To me blacklisting plugincontainer in AltTab seems like a reasonable fix for now, but Firefox devs would probably also be interested in fixing it at some point unless there is some security aspect in that these are sandboxed processes. I can try to report this if I manage to create a more simple POC.

Should I turn my AltTab patch above into a PR?

@lwouis
Copy link
Owner

lwouis commented Jan 17, 2023

AltTab filters out processes to only listen to processes that could spawn windows.

This org.mozilla.plugincontainer process has an activationPolicy of accessory, which implies it could spawn windows. It also passes other checks that AltTab uses to filter out processes.

In other words, this process is setup by Mozilla as a process that accessibility apps, such as AltTab, may want to monitor, as it could spawn windows at any time, and these accessibility apps would then need to know about those to assist the user.

However, it seems that we can never subscribe to their accessibility events. This seems to indicate that either (a) they contain logic bugs that prevent them from being observed, or (b) that they shouldn't be flagged as accessory if they never have a chance to spawn a window.

In order words, Mozilla should fix those. I'm not a fan of complexifying AltTab's codebase with names of specific companies. However, it's been done before when we know the company will not step up and fix their issue.

Should I turn my AltTab patch above into a PR?

No. It we integrate this, it should be done upstream. Before the observeEvents. Probably here, we should ignore this process since we already know it will never be possible to listen to it later on.

@joshuataylor
Copy link

I believe it's not just Firefox, it's actually Webkit(?) as well, or certain configurations that use this. Jetbrains toolbox triggers this, which uses webkit I believe (https://blog.jetbrains.com/kotlin/2021/12/compose-multiplatform-toolbox-case-study/).

@siikamiika
Copy link

Looked into this again. Here's a minimal POC for the issue that I made by copying the relevant code in AltTab:

// compile:
// swiftc filename.swift
import Cocoa

func axObserverCallback(observer: AXObserver, element: AXUIElement, notificationName: CFString, _: UnsafeMutableRawPointer?) -> Void {
    /* print(observer, element, notificationName) */
}

let apps = NSWorkspace.shared.runningApplications
for app in apps {
    let pid = app.processIdentifier
    let axUiElement = AXUIElementCreateApplication(pid)
    var axObserver: AXObserver? = nil
    AXObserverCreate(pid, axObserverCallback, &axObserver)
    AXObserverAddNotification(axObserver!, axUiElement, kAXFocusedWindowChangedNotification as CFString, nil)
    print(app.activationPolicy.rawValue, app, axUiElement)
}
...
1 <NSRunningApplication: 0x600000d92e80 (org.mozilla.plugincontainer - 9862) LSASN:{hi=0x0;lo=0x3d73d7}> <AXUIElement Application 0x600002d9e070> {pid=9862}
...

Like you said org.mozilla.plugincontainer are marked as accessory (enum value 1). I guess the possible fix for Mozilla would be to change it to prohibited (2).

@lwouis does this make sense? (I can also just create a PR)

diff --git a/src/logic/Applications.swift b/src/logic/Applications.swift
index 80130da..d5df8b9 100644
--- a/src/logic/Applications.swift
+++ b/src/logic/Applications.swift
@@ -110,7 +110,7 @@ class Applications {
     private static func isActualApplication(_ app: NSRunningApplication) -> Bool {
         // an app can start with .activationPolicy == .prohibited, then transition to != .prohibited later
         // an app can be both activationPolicy == .accessory and XPC (e.g. com.apple.dock.etci)
-        return (isNotXpc(app) || isAndroidEmulator(app)) && !app.processIdentifier.isZombie()
+        return (isNotXpc(app) || isAndroidEmulator(app)) && !app.processIdentifier.isZombie() && !isInvalidActivationPolicy(app)
     }
 
     private static func isNotXpc(_ app: NSRunningApplication) -> Bool {
@@ -128,6 +128,12 @@ class Applications {
         return app.processIdentifier != ProcessInfo.processInfo.processIdentifier
     }
 
+    // these apps report their activationPolicy as accessory but do not support AXObserverAddNotification
+    private static func isInvalidActivationPolicy(_ app: NSRunningApplication) -> Bool {
+        let bundleId = app.bundleIdentifier
+        return app.activationPolicy == .accessory && bundleId == "org.mozilla.plugincontainer"
+    }
+
     static func isAndroidEmulator(_ app: NSRunningApplication) -> Bool {
         // NSRunningApplication provides no way to identify the emulator; we pattern match on its KERN_PROCARGS
         if app.bundleIdentifier == nil,

@joshuataylor I tried Jetbrains toolbox, and while I did get some log spam, it stopped as soon as the window became visible. It also happens to me with System Settings.

siikamiika added a commit to siikamiika/alt-tab-macos that referenced this issue Jan 26, 2023
As a special case, make Applications.isActualApplication return false
for Firefox plugincontainer.

github: fix lwouis#2225
siikamiika added a commit to siikamiika/alt-tab-macos that referenced this issue Jan 26, 2023
As a special case, make Applications.isActualApplication return false
for Firefox plugincontainer so that it is not observed with the
accessibility API. These processes do not support AX observer
notifications although they report activationPolicy=accessory.

ref:
https://developer.apple.com/documentation/appkit/nsapplication/activationpolicy/accessory

github: fix lwouis#2225
@siikamiika
Copy link

@lwouis
Copy link
Owner

lwouis commented Jan 26, 2023

That's wonderful that Mozilla fixed it, thank you @siikamiika.

FYI, things like LSBackgroundOnly and LSUIElement in the plist are static declaration. They can be overriden later in the app lifecycle, at runtime, with OS API calls. So they only tell you what the process will launch with. A few milliseconds later, it may switch to other value of .activationPolicy for instance.

@burdo3417
Copy link
Author

Thanks for the hard work @siikamiika.
I guess I'll wait for the alt-tab or firefox update.

@joshuataylor
Copy link

This also happens when System Preferences is closed, on MacOS Monterey 12.6.3 (21G419) as noted above.

If you run the Python script above, you can reproduce this as follows:

  1. Open Console (it's in Applications -> Utilities -> Console)
  2. Run the python script
  3. Open System Preferences
  4. Note the pid in the python script (added 2023-02-03T22:41:31.006542 psutil.Process(pid=16156, name='System Preferences', status='running', started='22:41:31')
  5. Close System Preferences (Command+Q to ensure it's closed)
  6. Note the PID has been terminated (removed 2023-02-03T22:41:33.790060 psutil.Process(pid=16156, name='System Preferences', status='terminated', started='22:41:31'))
  7. Alt Tab
  8. See the log entry appear in Console

@burdo3417
Copy link
Author

I think the bug was fixed on Firefox v111.
Can anyone else confirm?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants