xcodebuild/xcbeautify hangs when a run script build phase containing only `export` is run

[hisaac]

Got a bit of a weird one here!

In my Xcode project, I've got a run script build phase that just contains export. This is to print out the environment variables to the log.

For some reason, in version 0.21.0 of xcbeautify, the build gets hung up on that build phase.

I went through the process of git bisecting between 0.20.0 and 0.21.0, and the commit that seems to be the cause of the issue is this one: 215be3c875a19ad06fa99aeef749439fff8fff92.

I'm not sure why that change is causing things to hang, but in my testing, it does cause the problem.

Steps to Reproduce

Here's an example project you can use for testing: xcbeautify-test-project.zip

1. Ensure xcbeautify 0.21.0 is installed
2. Navigate your terminal to the root of the project
3. Run xcrun xcodebuild | xcbeautify
4. Note that the build hangs at the "Running script Print environment variables" phase
5. Open the project in Xcode
6. Delete the "Print environment variables" build phase
7. Repeat step 3
8. Note that the build succeeds as expected

[hisaac]

cc @cpisciotta

[choulepoka]

I am not sure if related, but our CI started to hang when building a Mac Catalyst release archive build (but works for the regular iOS)

For now, my work-around is to stop using xcbeautify on my my archive for catalyst.

[choulepoka]

Also, i noticed that the release of the new version of xcbeautify matches the moment that our build almost doubled in elapsed time. On a hunch, I decided to remove xcbeautify from the build scrips, and builds times went down back to normal.

Again, I have not checked the changes between version, but there seem to be a big regression in overall performance. between 0.20 and 0.21.

[kpriemchenko]

After I updated xcbeautify to version 0.21 on CI server, the .xcactivitylog files are not created at all after xcodebuild command. They are created when I use version 0.20 or earlier.

[cpisciotta]

Thanks everyone for the feedback! Sorry for the inconvenience, and I'll work to get a fix published very soon!

[cpisciotta]

After I updated xcbeautify to version 0.21 on CI server, the .xcactivitylog files are not created at all after xcodebuild command. They are created when I use version 0.20 or earlier.

Can you share your xcodebuild command? xcbeautify shouldn't interrupt its creation via xcodebuild. I'm not aware of anything from 0.20 to 0.21 that I'd expect to change this behavior.

[kpriemchenko]

Can you share your xcodebuild command? xcbeautify shouldn't interrupt its creation via xcodebuild. I'm not aware of anything from 0.20 to 0.21 that I'd expect to change this behavior.

The command is composed by Fastlane (2.213.0). Here it is, slightly redacted: set -o pipefail && env NSUnbufferedIO=YES xcodebuild -workspace <workspaceName>.xcworkspace -scheme <schemeName> -configuration Debug -derivedDataPath /Users/<username>/Library/Developer/Xcode/DerivedData/<appName>-<hash> -destination 'platform=iOS Simulator,id=<GUID>' build-for-testing | tee '/Users/<username>/Library/Logs/scan/<logFileName>.log' | xcbeautify

On my local machine xcactivity log is created after this command, but on CI server it is not. But I'm not sure how exactly shell commands are executed on the CI server.

[jaysoffian]

This is a bad regex:

https://github.com/tuist/xcbeautify/blob/215be3c875a19ad06fa99aeef749439fff8fff92/Sources/XcbeautifyLib/Pattern.swift#L60

"^[SwiftCompile|CompileSwift].*?((?:\.|[^ ])+\/((?:\.|[^ ])+\.(?:m|mm|c|cc|cpp|cxx|swift)))\s.*\((in target: (.*)|in target '(.*)' from project '.*')\)"

I'm pretty sure the change that introduced it meant it to be:

"^(SwiftCompile|CompileSwift).*?((?:\.|[^ ])+\/((?:\.|[^ ])+\.(?:m|mm|c|cc|cpp|cxx|swift)))\s.*\((in target: (.*)|in target '(.*)' from project '.*')\)"

The intent is to match the literal strings SwiftCompile or CompileSwift. By using brackets instead of parenthesis, it's matching any of the letters inside the brackets S, w, i, ...

That can't be what was intended.

The regex should also avoid using .*? if possible since the non-greedy (lazy) match can cause really bad performance due to backtracking.

Watching a build with this change, I see xcbeautify eating up a ton of CPU.

Using multiple greedy matches is also a potential performance issue, because again, backtracking, but not as bad as the lazy operator.

So for example, instead of '(.*)' consider using '([^']*)' unless the concern is a single quote in the filename.

There's a good discussion on the implications of backtracking in this Cloudflare blog post:

https://blog.cloudflare.com/details-of-the-cloudflare-outage-on-july-2-2019/

Specifically see "Appendix: About Regular Expression Backtracking".

[jaysoffian]

Timing on a 96,597 xcodebuild log with xcpretty:

$ time ./xcpretty/bin/xcpretty < "$LOG" > /dev/null

real    0m9.841s
user    0m9.348s
sys 0m0.428s

With xcbeautify-0.20.0:

$ time ~/Downloads/xcbeautify < "$LOG" > /dev/null

real    0m6.389s
user    0m6.257s
sys 0m0.095s

With xcbeautify @ bf92ae98aa44ee21dac5c8527a1f09c688f325cc but using this regex:

    case compile = #"^(SwiftCompile|CompileSwift).*?((?:\.|[^ ])+\/((?:\.|[^ ])+\.(?:m|mm|c|cc|cpp|cxx|swift)))\s.*\((in target: (.*)|in target '(.*)' from project '.*')\)"#

$ time ~/Downloads/xcb/xcbeautify < "$LOG" > /dev/null

real    0m48.787s
user    0m47.843s
sys 0m0.573s

So it's still a significant performance regression even with the likely intended pattern.

I'm working through the regex using https://metacpan.org/pod/Regexp::Debugger to see what I can do. It doesn't help that the original pattern has no comments. It's unfortunate that these regexes aren't commented to explain what they're trying to do.

Reverting to the previous pattern: ^Compile[\w]+\s.+?\s((?:\.|[^ ])+\/((?:\.|[^ ])+\.(?:m|mm|c|cc|cpp|cxx|swift)))\s.*\((in target: (.*)|in target '(.*)' from project '.*')\) I'm still seeing 48 seconds:

$ time ~/Downloads/xcb/xcbeautify < "$LOG" > /dev/null

real    0m49.247s
user    0m48.615s
sys 0m0.456s

This is a significant performance regression since 0.20.0. Just to make sure I was comparing apples to apples, I compiled locally checking out the 0.20.0 tag with the same log file:

$ time ~/Downloads/xcb/xcbeautify < "$LOG" > /dev/null

real    0m6.415s
user    0m6.249s
sys 0m0.076s

[jaysoffian]

It looks like all of the patterns in xcbeautify need to be revisited. Any single long line can cause its patterns to backtrack catastrophically. I just found another that causes 0.20.0 to fail.

The context is this output from xcodebuild:

SwiftEmitModule normal x86_64 Emitting\ module\ for\ SomeApp (in target 'SomeApp' from project 'SomeProject')
    cd /Users/example/workspace/src/git.example.com/example/IOS-Example
    builtin-swiftTaskExecution -- /Applications/Xcode-14.3.1.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/swift-frontend @/Users/example/workspace/src/git.example.com/example/IOS-Example/build/Build/Intermediates.noindex/Example.build/Debug-iphonesimulator/Example.build/Objects-normal/x86_64/arguments-7328256046094096924.resp

That then emits two JSON objects each preceded with an integer:

232703
{
  "kind": "began",
  "name": "compile",
  ...
}

Followed by:

260870
{
  "kind": "finished",
  "name": "compile",
  "pid": 5429,
  "output": "...extremely long line of 260733 characters...",
  "process": {
    "real_pid": 5429
  },
  "exit-status": 0
}

The output line is what chokes xcbeautify. I'll try to track it down further.

Unfortunately, xcbeautify will have this potential vulnerability unless it avoids backtracking patterns.

[github-actions[bot]]

Hola 👋,

We want to inform you that the issue has been marked as stale. This means that there hasn't been any activity or updates on it for quite some time, and it's possible that it may no longer be relevant or actionable. If you still believe that this issue is valid and requires attention, please provide an update or any additional information that can help us address it. Otherwise, we may consider closing it in the near future. Thank you for your understanding.

[hisaac]

Thanks for the reminder github-actions bot. I think this issue can be closed for now. Thanks for the help in diagnosis folks!