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"

Consider this:

Exception Type:    EXC_BREAKPOINT (SIGTRAP)
Exception Codes:   0x0000000000000001, 0x0000000102c799bc

This typically means that the app trapped, that is, it detected an internal error and deliberately crashed. For example, if you force unwrap an option that’s nil, you’ll trap like this.

Now look at the backtrace:

Thread 1 Crashed::  Dispatch queue: com.apple.root.utility-qos
0 DIM                     … 0x102c6c000 + 55740
1 DIM                     … 0x102c6c000 + 128212
2 libdispatch.dylib       … _dispatch_call_block_and_release + 32
3 libdispatch.dylib       … _dispatch_client_callout + 16
4 libdispatch.dylib       …  + 32
5 libdispatch.dylib       … _dispatch_root_queue_drain + 736
6 libdispatch.dylib       … _dispatch_worker_thread2 + 180
7 libsystem_pthread.dylib … _pthread_wqthread + 232
8 libsystem_pthread.dylib … start_wqthread + 8

frames 8 through 2 are Dispatch (GCD) machinery. Frame 1 is your code, which calls frame 0, which trapped. To learn more about this you need to symbolicate frames 1 and 0. See Adding identifiable symbol names to a crash report.

Share and Enjoy

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

That's what I did. It resolved to a line which tried to use the object to access the AppleScript. Before Apple's change, it could not reach that code.

I create the object which loads AppleScriptObjC/script on the .userInteractive queue. I then dispatch back to the main queue. There I test if the object is nil or if there is a problem calling the script. If so, I display error sheet and quit. Otherwise, UserDefaults is loaded and startup finishes accordingly. These tests to check if AppleScriptObjC/script correctly loaded failed to work.

Messy, but worked for over five years, until now.

btw, the picture of the Devices and Simulations is out-of-date along with the instructions. I did cli.

You have the crash report, GitHub has the actual source for that version in Releases. Uploaded .dSYM also. (https://github.com/com-entonos/Desktop-Icon-Manager/releases/tag/4.5.1)

Appreciate the interest,

GitHub has the actual source for that version in Releases

OK. I downloaded the app, the .dSYM, and the source code and took a look.

First, the crash report has this:

Binary Images:
       0x102c6c000 -        0x102c9ffff DIM arm64  <3e247524da7930099f63cd12ace4ab0e> …/DIM

I used dwarfdump to confirm that I have the right .dSYM:

% dwarfdump --uuid DIM.app/Contents/MacOS/DIM
UUID: 7A4DAC69-55A2-3D1B-B9E0-6A14AB2D5EEA (x86_64) DIM.app/Contents/MacOS/DIM
UUID: 3E247524-DA79-3009-9F63-CD12ACE4AB0E (arm64) DIM.app/Contents/MacOS/DIM

I then symbolicated those frames:

% atos -l 0x102c6c000 -o DIM.app.dSYM 0x102c799bc 0x102c8b4d4
closure #1 in ViewController.restore(_:) (in DIM) (ViewController.swift:207)
thunk for @escaping @callee_guaranteed () -> () (in DIM) + 28

Plugging that into the backtrace, I get this:

Thread 1 Crashed::  Dispatch queue: com.apple.root.utility-qos
0 DIM                     … 0x102c6c000 + 55740 closure #1 in ViewController.restore(_:) (in DIM) (ViewController.swift:207)
1 DIM                     … 0x102c6c000 + 128212 thunk for @escaping @callee_guaranteed () -> () (in DIM) + 28
2 libdispatch.dylib       … _dispatch_call_block_and_release + 32
3 libdispatch.dylib       … _dispatch_client_callout + 16
4 libdispatch.dylib       …  + 32
5 libdispatch.dylib       … _dispatch_root_queue_drain + 736
6 libdispatch.dylib       … _dispatch_worker_thread2 + 180
7 libsystem_pthread.dylib … _pthread_wqthread + 232
8 libsystem_pthread.dylib … start_wqthread + 8

I then loaded the app up in LLDB:

% lldb DIM.app
(lldb) target create "DIM.app"
Current executable set to '/Users/quinn/Desktop/DesktopIconManager4.5.1/DIM.app' (arm64).

and looked at the actual crashing address:

(lldb) disas -s 0x100000000+55740
DIM`Swift runtime failure: Unexpectedly found nil while unwrapping an Optional value:
DIM[0x10000d9bc] <+1288>: brk    #0x1

Note The crash report shows that 55740 is the offset from the start of the image to the crashing instruction. LLDB loads the main image at 0x100000000, that is, after the 4 GiB page zero segment. By adding these together we get the crashing address for the LLDB context.

The brk is a trap instruction for 64-bit Apple silicon code. When Swift inserts such a trap, it tries to put it at a unique address and add a symbol for that address that indicates the type of trap. Hence the nice output from LLDB.

Now let’s look at the source address indicated by the symbolication, line 207 of ViewController.swift:

203 // restore from arrangement given by name
204 func restore(_ name: String) {
205     updateUI("Restoring Icon Positions...")
206     DispatchQueue.global(qos: .utility).async { [unowned self] in
207         self.setSet(set: self.arrangements[name]!)
208         self.dim!.numOnDesktop = 0
            …
213     }
214 }

It seems most likely that self.arrangements[name] is nil [1]. This confirms my earlier assertion that this is an issue with your code rather than the system-level issue that bwill was bumping in to.

Looking further into the code, I bumped into some serious concurrency holes. You access self.arrangements from both the the main thread (via the timer scheduled in refreshTimer()) and a Dispatch global concurrent queue (via the code shown above). The Swift concurrency model considers this undefined behavior. Honestly, you’re lucky that you crashed so ‘cleanly’; concurrency bugs are often much harder to find.

I recommend that you take a step back, look at the big picture of the concurrency within this app, decide on a plan, and implement that. And if were in your shoes I’d enable the Swift 6 language mode, whereupon the compiler will help you avoid issues like this.

Oh, and I also recommend that you not use Dispatch global concurrent queues. See Avoid Dispatch Global Concurrent Queues has the full story on that front.

Share and Enjoy

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

[1] It wouldn’t surprise me if the actual issue was that self.dim was nil, but self.dim has the same concurrency issues as self.arrangements.

Thank you. Particularly for the step-by-step, very informative.

The algorithm should have insured arrangements[name] is not nil well before func restore was called (therefore no test to confirm).

Appreciate your time and efforts- never fun looking at another's code. Also understand your concerns about concurrency. They are valid.

XProtect makes app hang when running an AppleScript
 
 
Q