[maccatalyst][arm64] Flaky test failure in CI : Failed to get bundle information #63572

MaximLipnin · 2022-01-10T09:12:17Z

It's a flaky test failure - happens on some rolling builds, e.g.

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-f31599a56a244094b0/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests/1/console.0bcd8cf3.log?sv=2019-07-07&se=2022-01-29T20%3A27%3A51Z&sr=c&sp=rl&sig=5fySqKzsC5uO1MRG386a0QXb9%2F1gy7vUks196tsrzKs%3D

+ sudo launchctl asuser 505 sudo -u helix-runner sh ./xharness-runner.apple.sh --target maccatalyst --command-timeout 2280 --timeout 00:30:00 --launch-timeout 00:30:00 --includes-test-runner --expected-exit-code 0 --app /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app --output-directory /tmp/helix/working/A2A0091A/w/BF0409FF/uploads
XHarness command issued: apple test --app /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app --output-directory /tmp/helix/working/A2A0091A/w/BF0409FF/uploads --target maccatalyst --timeout 00:30:00 --xcode /Applications/Xcode13.app -v --launch-timeout 00:30:00
[12:28:45] info: Preparing run for maccatalyst
[12:28:45] info: Getting app bundle information from '/tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app'
[12:28:45] dbug: 
[12:28:45] dbug: Running /usr/libexec/PlistBuddy -c "Print CFBundleName" /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app/Contents/Info.plist
[12:28:45] dbug: Process PlistBuddy exited with 0
[12:28:45] dbug: 
[12:28:45] dbug: Running /usr/libexec/PlistBuddy -c "Print CFBundleIdentifier" /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app/Contents/Info.plist
[12:29:01] dbug: Process 56292 didn't exit within 00:00:15 and will be killed
[12:29:01] dbug: Killing process tree of 56292...
[12:29:01] dbug: Pids to kill: 56292
[12:29:01] dbug: Running lldb diagnostics for pid 56292
[12:29:01] dbug: Printing backtrace for pid=56292
[12:29:10] dbug: (lldb) command source -s 0 '/var/folders/2_/8s76ml311gv142wwl15flm3c0000gs/T/tmp6WvMua.tmp'
[12:29:10] dbug: Executing commands in '/var/folders/2_/8s76ml311gv142wwl15flm3c0000gs/T/tmp6WvMua.tmp'.
[12:29:10] dbug: (lldb) process attach --pid 56292
[12:29:10] dbug: error: attach failed: no such process.
[12:29:10] dbug: 56292 Execution timed out after 15 seconds and the process was killed.
[12:29:10] dbug: Process PlistBuddy exited with 0
[12:29:10] fail: Failed to get bundle information: net.dot.Microsoft.Extensions.Configuration.EnvironmentVariables.Tests
                 
[12:29:10] dbug: Saving diagnostics data to '/tmp/helix/working/A2A0091A/w/BF0409FF/e/diagnostics.json'
XHarness exit code: 79 (FAILED_TO_GET_BUNDLE_INFO)

The text was updated successfully, but these errors were encountered:

ghost · 2022-01-10T09:12:20Z

Tagging subscribers to 'os-maccatalyst': @steveisok, @akoeplinger
See info in area-owners.md if you want to be subscribed.

Issue Details

It's a flaky test failure - happens on some rolling builds, e.g.

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-f31599a56a244094b0/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests/1/console.0bcd8cf3.log?sv=2019-07-07&se=2022-01-29T20%3A27%3A51Z&sr=c&sp=rl&sig=5fySqKzsC5uO1MRG386a0QXb9%2F1gy7vUks196tsrzKs%3D

+ sudo launchctl asuser 505 sudo -u helix-runner sh ./xharness-runner.apple.sh --target maccatalyst --command-timeout 2280 --timeout 00:30:00 --launch-timeout 00:30:00 --includes-test-runner --expected-exit-code 0 --app /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app --output-directory /tmp/helix/working/A2A0091A/w/BF0409FF/uploads
XHarness command issued: apple test --app /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app --output-directory /tmp/helix/working/A2A0091A/w/BF0409FF/uploads --target maccatalyst --timeout 00:30:00 --xcode /Applications/Xcode13.app -v --launch-timeout 00:30:00
[12:28:45] info: Preparing run for maccatalyst
[12:28:45] info: Getting app bundle information from '/tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app'
[12:28:45] dbug: 
[12:28:45] dbug: Running /usr/libexec/PlistBuddy -c "Print CFBundleName" /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app/Contents/Info.plist
[12:28:45] dbug: Process PlistBuddy exited with 0
[12:28:45] dbug: 
[12:28:45] dbug: Running /usr/libexec/PlistBuddy -c "Print CFBundleIdentifier" /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app/Contents/Info.plist
[12:29:01] dbug: Process 56292 didn't exit within 00:00:15 and will be killed
[12:29:01] dbug: Killing process tree of 56292...
[12:29:01] dbug: Pids to kill: 56292
[12:29:01] dbug: Running lldb diagnostics for pid 56292
[12:29:01] dbug: Printing backtrace for pid=56292
[12:29:10] dbug: (lldb) command source -s 0 '/var/folders/2_/8s76ml311gv142wwl15flm3c0000gs/T/tmp6WvMua.tmp'
[12:29:10] dbug: Executing commands in '/var/folders/2_/8s76ml311gv142wwl15flm3c0000gs/T/tmp6WvMua.tmp'.
[12:29:10] dbug: (lldb) process attach --pid 56292
[12:29:10] dbug: error: attach failed: no such process.
[12:29:10] dbug: 56292 Execution timed out after 15 seconds and the process was killed.
[12:29:10] dbug: Process PlistBuddy exited with 0
[12:29:10] fail: Failed to get bundle information: net.dot.Microsoft.Extensions.Configuration.EnvironmentVariables.Tests
                 
[12:29:10] dbug: Saving diagnostics data to '/tmp/helix/working/A2A0091A/w/BF0409FF/e/diagnostics.json'
XHarness exit code: 79 (FAILED_TO_GET_BUNDLE_INFO)

Author:	MaximLipnin
Assignees:	-
Labels:	`os-maccatalyst`
Milestone:	-

dotnet-issue-labeler · 2022-01-10T09:12:22Z

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

ghost · 2022-01-11T16:08:33Z

Tagging subscribers to this area: @directhex
See info in area-owners.md if you want to be subscribed.

Issue Details

It's a flaky test failure - happens on some rolling builds, e.g.

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-f31599a56a244094b0/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests/1/console.0bcd8cf3.log?sv=2019-07-07&se=2022-01-29T20%3A27%3A51Z&sr=c&sp=rl&sig=5fySqKzsC5uO1MRG386a0QXb9%2F1gy7vUks196tsrzKs%3D

+ sudo launchctl asuser 505 sudo -u helix-runner sh ./xharness-runner.apple.sh --target maccatalyst --command-timeout 2280 --timeout 00:30:00 --launch-timeout 00:30:00 --includes-test-runner --expected-exit-code 0 --app /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app --output-directory /tmp/helix/working/A2A0091A/w/BF0409FF/uploads
XHarness command issued: apple test --app /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app --output-directory /tmp/helix/working/A2A0091A/w/BF0409FF/uploads --target maccatalyst --timeout 00:30:00 --xcode /Applications/Xcode13.app -v --launch-timeout 00:30:00
[12:28:45] info: Preparing run for maccatalyst
[12:28:45] info: Getting app bundle information from '/tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app'
[12:28:45] dbug: 
[12:28:45] dbug: Running /usr/libexec/PlistBuddy -c "Print CFBundleName" /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app/Contents/Info.plist
[12:28:45] dbug: Process PlistBuddy exited with 0
[12:28:45] dbug: 
[12:28:45] dbug: Running /usr/libexec/PlistBuddy -c "Print CFBundleIdentifier" /tmp/helix/working/A2A0091A/w/BF0409FF/e/Microsoft.Extensions.Configuration.EnvironmentVariables.Tests.app/Contents/Info.plist
[12:29:01] dbug: Process 56292 didn't exit within 00:00:15 and will be killed
[12:29:01] dbug: Killing process tree of 56292...
[12:29:01] dbug: Pids to kill: 56292
[12:29:01] dbug: Running lldb diagnostics for pid 56292
[12:29:01] dbug: Printing backtrace for pid=56292
[12:29:10] dbug: (lldb) command source -s 0 '/var/folders/2_/8s76ml311gv142wwl15flm3c0000gs/T/tmp6WvMua.tmp'
[12:29:10] dbug: Executing commands in '/var/folders/2_/8s76ml311gv142wwl15flm3c0000gs/T/tmp6WvMua.tmp'.
[12:29:10] dbug: (lldb) process attach --pid 56292
[12:29:10] dbug: error: attach failed: no such process.
[12:29:10] dbug: 56292 Execution timed out after 15 seconds and the process was killed.
[12:29:10] dbug: Process PlistBuddy exited with 0
[12:29:10] fail: Failed to get bundle information: net.dot.Microsoft.Extensions.Configuration.EnvironmentVariables.Tests
                 
[12:29:10] dbug: Saving diagnostics data to '/tmp/helix/working/A2A0091A/w/BF0409FF/e/diagnostics.json'
XHarness exit code: 79 (FAILED_TO_GET_BUNDLE_INFO)

Author:	MaximLipnin
Assignees:	-
Labels:	`untriaged`, `area-Infrastructure-mono`, `os-maccatalyst`
Milestone:	-

steveisok · 2022-01-11T16:20:16Z

@premun Any idea what would be the cause?

premun · 2022-01-11T17:09:50Z

Seems like Plistbuddy, which is the apple tool that pulls the properties out of plists for us, times out (but also returns the right response).

This

[12:29:10] fail: Failed to get bundle information: net.dot.Microsoft.Extensions.Configuration.EnvironmentVariables.Tests

comes from here:

var result = await _processManager.ExecuteCommandAsync(PlistBuddyPath, args, log, commandOutput, commandOutput, TimeSpan.FromSeconds(15), cancellationToken: cancellationToken);

if (!result.Succeeded)
{
    throw new Exception($"Failed to get bundle information: {commandOutput}");
}

We can bump the 15 second timeout or we can ignore the timeout. This operation should be quick as it only parses the XML so not sure bumping will help as it might be just hanging somewhere.

steveisok · 2022-01-11T17:21:36Z

Since this appears to be flaky, can we bump the timeout and see if that helps?

premun · 2022-01-12T11:39:20Z

The new XHarness with increased timeout is here: #63680

premun · 2022-01-12T15:32:11Z

It's merged so let's give it a few days for it to propagate to all PR branches and let's see if we see this still

MaximLipnin · 2022-01-19T11:35:00Z

It still happens after increasing the timeout:

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-63cfd7f85b5c41d793/System.Resources.Writer.Tests/1/console.92f42230.log?sv=2019-07-07&se=2022-02-08T08%3A22%3A15Z&sr=c&sp=rl&sig=BPvUj6gfuaH6QiGS4AQl7mrVa%2FWz9udnvIKLxCTAADY%3D

premun · 2022-01-19T12:33:59Z

Then I propose reverting the timeout and just ignoring the fact it times out since PlistBuddy still returns what we need. If it does not, we will fail later

premun · 2022-01-19T12:50:02Z

@MaximLipnin do you know how to get logs from more repros easily? I am wondering if it only happens when getting CFBundleIdentifier

MaximLipnin · 2022-01-19T13:06:26Z

@MaximLipnin do you know how to get logs from more repros easily? I am wondering if it only happens when getting CFBundleIdentifier

Maybe something like this?

WorkItems 
| where Started > now(-30d)  
| where ExitCode == 79
| join kind= inner (
   Jobs  | where Started > now(-30d) | project  QueueName , JobId, Build, Type, Source 
) on JobId
| summarize count() by ExitCode, QueueName, Started, Source
| order by Started desc

premun · 2022-01-28T09:00:07Z

@MaximLipnin it has been a couple of days. Are we seeing any more of these issues?

MaximLipnin · 2022-01-28T09:18:27Z

@premun Seems it's gone, at least, I dont see it anymore

MaximLipnin · 2022-01-28T09:22:12Z

I'm closing it as resolved, thanks to @premun for addressing.

Since #63572 no longer happens in CI, we can promote MacCatalyst templates from the runtime-staging to the runtime-extra-platforms pipeline. For now we will keep MacCatalyst arm64 legs in runtime-staging as they are not stable on OSX 11.00 queues (see #64452 (comment)). Co-authored-by: Steve Pfister <steve.pfister@microsoft.com> Co-authored-by: Alexander Köplinger <alex.koeplinger@outlook.com>

MaximLipnin added the os-maccatalyst MacCatalyst OS label Jan 10, 2022

dotnet-issue-labeler bot added the untriaged New issue has not been triaged by the area owner label Jan 10, 2022

jeffschwMSFT added the area-Infrastructure-mono label Jan 11, 2022

steveisok removed the untriaged New issue has not been triaged by the area owner label Jan 11, 2022

steveisok added this to the 7.0.0 milestone Jan 11, 2022

premun mentioned this issue Jan 11, 2022

Bump timeout for querying Info.plist dotnet/xharness#803

Merged

premun mentioned this issue Jan 19, 2022

Add retries to PlistBuddy calls dotnet/xharness#805

Merged

MaximLipnin closed this as completed Jan 28, 2022

MaximLipnin mentioned this issue Jan 28, 2022

Move MacCatalyst to runtime-extra-platforms pipeline #64452

Merged

ghost locked as resolved and limited conversation to collaborators Feb 27, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[maccatalyst][arm64] Flaky test failure in CI : Failed to get bundle information #63572

[maccatalyst][arm64] Flaky test failure in CI : Failed to get bundle information #63572

MaximLipnin commented Jan 10, 2022

ghost commented Jan 10, 2022

dotnet-issue-labeler bot commented Jan 10, 2022

ghost commented Jan 11, 2022

steveisok commented Jan 11, 2022

premun commented Jan 11, 2022

steveisok commented Jan 11, 2022

premun commented Jan 12, 2022

premun commented Jan 12, 2022

MaximLipnin commented Jan 19, 2022

premun commented Jan 19, 2022

premun commented Jan 19, 2022

MaximLipnin commented Jan 19, 2022

premun commented Jan 28, 2022

MaximLipnin commented Jan 28, 2022

MaximLipnin commented Jan 28, 2022

[maccatalyst][arm64] Flaky test failure in CI : Failed to get bundle information #63572

[maccatalyst][arm64] Flaky test failure in CI : Failed to get bundle information #63572

Comments

MaximLipnin commented Jan 10, 2022

ghost commented Jan 10, 2022

dotnet-issue-labeler bot commented Jan 10, 2022

ghost commented Jan 11, 2022

steveisok commented Jan 11, 2022

premun commented Jan 11, 2022

steveisok commented Jan 11, 2022

premun commented Jan 12, 2022

premun commented Jan 12, 2022

MaximLipnin commented Jan 19, 2022

premun commented Jan 19, 2022

premun commented Jan 19, 2022

MaximLipnin commented Jan 19, 2022

premun commented Jan 28, 2022

MaximLipnin commented Jan 28, 2022

MaximLipnin commented Jan 28, 2022