xcodebuild/xcbeautify hangs when a run script build phase containing only `export` is run about xcbeautify HOT 12 CLOSED

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

from xcbeautify.

cc @cpisciotta

from xcbeautify.

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.

from xcbeautify.

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.

from xcbeautify.

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.

from xcbeautify.

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.

from xcbeautify.

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.

from xcbeautify.

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".

from xcbeautify.

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 @ bf92ae9 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

from xcbeautify.

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.

from xcbeautify.

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.

from xcbeautify.

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

from xcbeautify.