XProtect makes app hang when running an AppleScript

I now had the second user with 26.2. complaining about a hang in my app. The hang occurs when the first AppleScript for Mail is run. Here is the relevant section from the process analysis in Activity Monitor:

+                             2443 OSACompile  (in OpenScripting) + 52  [0x1b32b30f4]
+                               2443 SecurityPolicyTestDescriptor  (in OpenScripting) + 152  [0x1b32a2284]
+                                 2443 _SecurityPolicyTest(char const*, void const*, unsigned long)  (in OpenScripting) + 332  [0x1b32a2118]
+                                   2443 InterpreterSecurity_ScanBuffer  (in libInterpreterSecurity.dylib) + 112  [0x28c149304]
+                                     2443 -[InterpreterSecurity scanData:withSourceURL:]  (in libInterpreterSecurity.dylib) + 164  [0x28c148db4]
+                                       2443 -[XProtectScan beginAnalysisWithFeedback:]  (in XprotectFramework) + 544  [0x1d35a1e58]
+                                         2443 -[XPMalwareEvaluation initWithData:assessmentClass:]  (in XprotectFramework) + 92  [0x1d359ada4]
+                                           2443 -[XPMalwareEvaluation initWithRuleString:withExtraRules:withURL:withData:withAssessmentClass:feedback:]  (in XprotectFramework) + 36  [0x1d359b2a8]

My app is correctly signed and notarised. The first user had to completely uninstall/reinstall the app and the everything worked again.

Why does this happen? How can the problem be fixed?

Answered by DTS Engineer in 871339022

Thanks for attaching a sysdiagnose log to your bug (FB21334477). I took a look at the enclosed spin dump and I see this:

  Thread 0x222f6b    180 samples (216-395)    priority 31 (base 31)    cpu time 0.016s (43.3M cycles, 111.3M in…
  180  thread_start + 8 (libsystem_pthread.dylib + 7080) [0x19ea8cba8]
    180  _pthread_start + 136 (libsystem_pthread.dylib + 27656) [0x19ea91c08]
      180  ??? (XojoFramework + 1309844) [0x10569bc94]
        180  ??? (XojoFramework + 2624740) [0x1057dcce4]
          … redacted …
          180  -[NSAppleScript compileAndReturnError:] + 136 (Foundation + 9808488) [0x1a0c7da68]
            180  OSACompile + 52 (OpenScripting + 78068) [0x1bffa30f4]
              180  SecurityPolicyTestDescriptor + 152 (OpenScripting + 8836) [0x1bff92284]
                180  _SecurityPolicyTest(char const*, void const*, unsigned long) + 332 (OpenScripting + 8472) …
                  180  InterpreterSecurity_ScanBuffer + 112 (libInterpreterSecurity.dylib + 4868) [0x298e39304]
                    180  -[InterpreterSecurity scanData:withSourceURL:] + 164 (libInterpreterSecurity.dylib + 3…
                      180  -[XProtectScan beginAnalysisWithFeedback:] + 544 (XprotectFramework + 40536) [0x1e02…
                        180  -[XPMalwareEvaluation initWithData:assessmentClass:] + 92 (XprotectFramework + 116…
                          180  -[XPMalwareEvaluation initWithRuleString:withExtraRules:withURL:withData:withAss…
                            180  -[XPMalwareEvaluation initWithRuleString:withExtraRules:withURL:withData:force…
                              180  _dispatch_sync_f_slow + 148 (libdispatch.dylib + 71640) [0x19e8e47d8]
                                180  __DISPATCH_WAIT_FOR_QUEUE__ + 368 (libdispatch.dylib + 72736) [0x19e8e4c20]
                                  180  _dispatch_thread_event_wait_slow + 56 (libdispatch.dylib + 15116) [0x19e…
                                    180  __ulock_wait + 8 (libsystem_kernel.dylib + 10980) [0x19ea50ae4]
                                     *180  ??? (kernel.release.t8103 + 6504060) [0xfffffe0008defe7c]

Note I’ve redacted a bunch of frames because they contain your symbols and I wasn’t sure whether you were OK with me posting those details here.

There’s a couple of things I can tell from this:

  • This code is running on a secondary thread.
  • The -[XPMalwareEvaluation initWithRuleString:withExtraRules:withURL:withData:forcedRulesOnly:withAssessmentClass:feedback:] method is stuck within a dispatch_sync call.

Looking at the source for that routine, I see that it’s dispatching to the main queue. So, your stuck here because the main thread isn’t servicing the main queue.

Looking at the state of the main thread in the spin dump, I see that it’s spending a significant amount of time stuck here:

… elided …
  180  Thread.Start%%o<Thread> + 16 … redacted …
    180  ??? (XojoFramework + 2619288) [0x1057db798]
      180  ??? (XojoFramework + 2628580) [0x1057ddbe4]
        180  xojo::ConditionVariable::Wait(xojo::UniqueLock&) + 20 (XojoFramework + 1310640) [0x10569bfb0]
          180  __psynch_cvwait + 8 (libsystem_kernel.dylib + 17656) [0x19ea524f8]
           *180  ??? (pthread + 18508) [0xfffffe000bffd7ac]

I’m not sure what this is about. The Thread.Start… frame is your code, but the remaining frames are within your third-party runtime and it’s hard to tell what exactly it’s waiting on.

Regardless, the above should give you something to go on. To summarise:

  • You’re running an AppleScript.
  • Which is being scanned by XProtect.
  • Which is waiting for the main thread.
  • Which is stalled within the Xojo runtime.
  • As the result of your Thread.Start… code.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

Exact same problem with same stack trace for our app. We create an NSAppleScript option and it is now hanging when we call executeAndReturnError or compileAndReturnError.

Some more information:

  • My AppleScripts usually are very simple because the app does the heavy lifting. Think getting the accounts for Mail or the account type.
  • I have 2 places in the app where I use AppleScript. In the Setup the users determines which email she wants to archive from Mail. And then the user can archive the emails to a database. The Setup uses the AppleScripts in a thread. Archiving is threaded, too. But the AppleScripts are run on the main thread and before threading starts. The scripts run fine on the main thread. These are the same scripts which are used in the Setup!!!
  • I've moved the first AppleScript to osascript and now the second script hangs which is still using NSAppleScript.

The plan for today is to move more AppleScripts to osascript.

It’s hard to offer insight here without more information. Are you able to capture a sysdiagnose log while your app is hung? Well, get your user to capture that log, I guess.

See Bug Reporting > Profiles and Logs for advice on how to capture a sysdiagnose log.

Also, if your user is reluctant to send you the log, they can use Feedback Assistant to file the bug directly with Apple and then pass along the bug number for you to share here.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

After updating to the latest XProtect version I was able to see the hang, too. I've added a sysdiagnose to the ticket.

Thanks for attaching a sysdiagnose log to your bug (FB21334477). I took a look at the enclosed spin dump and I see this:

  Thread 0x222f6b    180 samples (216-395)    priority 31 (base 31)    cpu time 0.016s (43.3M cycles, 111.3M in…
  180  thread_start + 8 (libsystem_pthread.dylib + 7080) [0x19ea8cba8]
    180  _pthread_start + 136 (libsystem_pthread.dylib + 27656) [0x19ea91c08]
      180  ??? (XojoFramework + 1309844) [0x10569bc94]
        180  ??? (XojoFramework + 2624740) [0x1057dcce4]
          … redacted …
          180  -[NSAppleScript compileAndReturnError:] + 136 (Foundation + 9808488) [0x1a0c7da68]
            180  OSACompile + 52 (OpenScripting + 78068) [0x1bffa30f4]
              180  SecurityPolicyTestDescriptor + 152 (OpenScripting + 8836) [0x1bff92284]
                180  _SecurityPolicyTest(char const*, void const*, unsigned long) + 332 (OpenScripting + 8472) …
                  180  InterpreterSecurity_ScanBuffer + 112 (libInterpreterSecurity.dylib + 4868) [0x298e39304]
                    180  -[InterpreterSecurity scanData:withSourceURL:] + 164 (libInterpreterSecurity.dylib + 3…
                      180  -[XProtectScan beginAnalysisWithFeedback:] + 544 (XprotectFramework + 40536) [0x1e02…
                        180  -[XPMalwareEvaluation initWithData:assessmentClass:] + 92 (XprotectFramework + 116…
                          180  -[XPMalwareEvaluation initWithRuleString:withExtraRules:withURL:withData:withAss…
                            180  -[XPMalwareEvaluation initWithRuleString:withExtraRules:withURL:withData:force…
                              180  _dispatch_sync_f_slow + 148 (libdispatch.dylib + 71640) [0x19e8e47d8]
                                180  __DISPATCH_WAIT_FOR_QUEUE__ + 368 (libdispatch.dylib + 72736) [0x19e8e4c20]
                                  180  _dispatch_thread_event_wait_slow + 56 (libdispatch.dylib + 15116) [0x19e…
                                    180  __ulock_wait + 8 (libsystem_kernel.dylib + 10980) [0x19ea50ae4]
                                     *180  ??? (kernel.release.t8103 + 6504060) [0xfffffe0008defe7c]

Note I’ve redacted a bunch of frames because they contain your symbols and I wasn’t sure whether you were OK with me posting those details here.

There’s a couple of things I can tell from this:

  • This code is running on a secondary thread.
  • The -[XPMalwareEvaluation initWithRuleString:withExtraRules:withURL:withData:forcedRulesOnly:withAssessmentClass:feedback:] method is stuck within a dispatch_sync call.

Looking at the source for that routine, I see that it’s dispatching to the main queue. So, your stuck here because the main thread isn’t servicing the main queue.

Looking at the state of the main thread in the spin dump, I see that it’s spending a significant amount of time stuck here:

… elided …
  180  Thread.Start%%o<Thread> + 16 … redacted …
    180  ??? (XojoFramework + 2619288) [0x1057db798]
      180  ??? (XojoFramework + 2628580) [0x1057ddbe4]
        180  xojo::ConditionVariable::Wait(xojo::UniqueLock&) + 20 (XojoFramework + 1310640) [0x10569bfb0]
          180  __psynch_cvwait + 8 (libsystem_kernel.dylib + 17656) [0x19ea524f8]
           *180  ??? (pthread + 18508) [0xfffffe000bffd7ac]

I’m not sure what this is about. The Thread.Start… frame is your code, but the remaining frames are within your third-party runtime and it’s hard to tell what exactly it’s waiting on.

Regardless, the above should give you something to go on. To summarise:

  • You’re running an AppleScript.
  • Which is being scanned by XProtect.
  • Which is waiting for the main thread.
  • Which is stalled within the Xojo runtime.
  • As the result of your Thread.Start… code.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

Oh, one more thing. That dispatch_sync call being made by XProtect is doing some one-time initialisation. That initialisation has to be done on the main thread. So, you might be able to work around this by forcing that initialisation to run on the main thread in advance of all this secondary thread work. An easy way to do that would be to use NSAppleScript to run a trivial script from the main thread as part of your app init sequence.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

Thanks for the clarification, Quinn. That explains why the hang occurs and why the first AppleScript call needs to run on the main thread.

In my case, the problem is that this behavior appeared without documentation. My app legitimately automates Mail and has done so for years. Running AppleScripts from background threads is a normal pattern for this kind of software. Having the first call suddenly require main-thread initialization is a significant behavioral change.

There are some practical issues for developers:

• The change is not documented.

• The hangs are non-deterministic.

• There is no API to trigger or control the initialization.

• There is no error or diagnostic that would help identify the cause.

I understand that AppleScript can be an attack surface and that XProtect integration may be intentional. However, the current approach affects legitimate uses without giving developers a supported way forward.

If the platform requirement is that the first AppleScript runs on the main thread, Apple should state this clearly. Undocumented technical hoops do not stop attackers. They only make life harder for developers who are trying to use the system in a supported way.

I would appreciate it if you could pass along that this change has real-world impact on existing shipping software, and that documentation or a simple API would avoid a lot of confusion.

Thanks again for your time.

the problem is that this behavior appeared without documentation.

Understood. Unfortunately such is the nature of bugs. If we’d known about the developer impact of this change, we wouldn’t have shipped it. Or, if we had to ship it anyway, we would’ve called it out in the release notes.

Usually we’re able to flush out problems like this during the beta seed process, but this case is tricky because it seems to be triggered by the combination of macOS and XProtect changes )-:

If the platform requirement is that the first AppleScript runs on the main thread

I think you’ve misunderstood my previous posts. I’m not claiming that this is a change in “platform requirement”. IMO this is a bug that we should fix on our side. My suggestion to prime XProtect by running a dummy AppleScript from the main thread is a workaround, and I represented it as such (“you might be able to work around”).

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

XProtect makes app hang when running an AppleScript
 
 
Q