Failed to Install microsoft.dotnet.xharness.cli on Ubuntu.1804.Amd64.Open

[Anipik]

2021-02-04T23:33:27.6778889Z   Using Timeout: 00:30:00
2021-02-04T23:33:27.7099543Z   Done building Helix work items for scenario wasmtestonbrowser. Work item count: 214
2021-02-04T23:33:32.6833318Z   You can invoke the tool using the following command: xharness
2021-02-04T23:33:32.6834851Z   Tool 'microsoft.dotnet.xharness.cli' (version '1.0.0-prerelease.21103.1') was successfully installed.
2021-02-04T23:33:33.1576352Z   Sending Job to Ubuntu.1804.Amd64.Open...
2021-02-04T23:33:34.0405009Z   Tool 'microsoft.dotnet.xharness.cli' (version '1.0.0-prerelease.21103.1') is already installed.
2021-02-04T23:33:34.0406291Z   Tool 'microsoft.dotnet.xharness.cli' failed to install. This failure may have been caused by:
2021-02-04T23:33:34.0406944Z   
2021-02-04T23:33:34.0407664Z   * You are attempting to install a preview release and did not use the --version option to specify the version.
2021-02-04T23:33:34.0408283Z   * A package by this name was found, but it was not a .NET tool.
2021-02-04T23:33:34.0408865Z   * The required NuGet feed cannot be accessed, perhaps because of an Internet connection problem.
2021-02-04T23:33:34.0409386Z   * You mistyped the name of the tool.
2021-02-04T23:33:34.0409752Z   
2021-02-04T23:33:34.0410455Z   For more reasons, including package naming enforcement, visit https://aka.ms/failure-installing-tool
2021-02-04T23:33:34.1189953Z   Sending Job to Ubuntu.1804.Amd64.Open...

log https://dev.azure.com/dnceng/9ee6d478-d288-47f7-aacc-f6e6d082ae6d/_apis/build/builds/979753/logs/1920
build https://dev.azure.com/dnceng/public/_build/results?buildId=979753&view=results

This has failed a couple of times now

cc @dotnet/runtime-infrastructure @dotnet/dnceng

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.

[Anipik]

Failed again here https://dev.azure.com/dnceng/public/_build/results?buildId=981759&view=results

[premun]

I suspect there is a clash of two processes/threads trying to install the tool in the same directory:
https://github.com/dotnet/arcade/blob/938b3e8b4edcd96ca0f0cbbae63c87b3f51f7afe/src/Microsoft.DotNet.Helix/Sdk/tools/xharness-runner/XHarnessRunner.targets#L32

Checking the .binlog it really seems sendtohelixhelp.proj is now being called twice in parallel:

I will make a fix in the Arcade SDK.

[premun]

@Anipik actually on a closer look, the tool fails to install the second time but the build continues on just fine. The build you have sent fails a WASM test, so the issue is not within the CLI installation. You can see lower in the log:

2021-02-04T23:53:35.3291112Z /__w/1/s/.packages/microsoft.dotnet.helix.sdk/6.0.0-beta.21101.7/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets(78,5): error : Work item System.ServiceModel.Syndication.Tests in job 4d9377d7-3edc-4157-9062-068d3e4da601 has failed. [/__w/1/s/src/libraries/sendtohelixhelp.proj]
2021-02-04T23:53:35.3294263Z /__w/1/s/.packages/microsoft.dotnet.helix.sdk/6.0.0-beta.21101.7/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets(78,5): error : Failure log: https://helix.dot.net/api/2019-06-17/jobs/4d9377d7-3edc-4157-9062-068d3e4da601/workitems/System.ServiceModel.Syndication.Tests/console [/__w/1/s/src/libraries/sendtohelixhelp.proj]
2021-02-04T23:53:35.3344475Z ##[error].packages/microsoft.dotnet.helix.sdk/6.0.0-beta.21101.7/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets(78,5): error : (NETCORE_ENGINEERING_TELEMETRY=Test) Work item System.ServiceModel.Syndication.Tests in job 4d9377d7-3edc-4157-9062-068d3e4da601 has failed.

If you open https://helix.dot.net/api/2019-06-17/jobs/4d9377d7-3edc-4157-9062-068d3e4da601/workitems/System.ServiceModel.Syndication.Tests/console you will see that the tests ran inside wasm and one of them failed:

[23:46:19] fail: [FAIL] System.ServiceModel.Syndication.Tests.Atom10ItemFormatterTests.WriteTo_EmptyItem_SerializesExpected
[23:46:19] info: Assert.True() Failure
[23:46:19] info: Expected: True
[23:46:19] info: Actual:   False
[23:46:19] info:    at System.ServiceModel.Syndication.Tests.Atom10ItemFormatterTests.WriteTo_EmptyItem_SerializesExpected()
[23:46:19] info:    at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
[23:46:22] info: Finished:    System.ServiceModel.Syndication.Tests.dll
[23:46:22] info: 
[23:46:22] info: === TEST EXECUTION SUMMARY ===
[23:46:22] info: Total: 1308, Errors: 0, Failed: 1, Skipped: 0, Time: 5.453156s

You can also see the details about the failed test in the Test pane of AzDO build:
https://dev.azure.com/dnceng/public/_build/results?buildId=981759&view=ms.vss-test-web.build-test-results-tab

I will still make the fix later but it is not a blocking issue.

[Anipik]

Thanks @premun for taking a look

[ViktorHofer]

What's the reason for the duplicate invocation of sendtohelix.proj?

[trylek]

@ViktorHofer IIRC we run it separately for a "restore" and "build" phase but I may be mistaken, I haven't looked in a while.

[premun]

Actually, for this one, we send the Helix job twice. I don't think this is on purpose:

  Sent Helix Job; see work items at https://helix.dot.net/api/jobs/2149b727-53c7-4cec-b15c-ef3292790d64/workitems?api-version=2019-06-17
  Sent Helix Job; see work items at https://helix.dot.net/api/jobs/e585b358-f498-4a8c-85b5-e93a934fe9f5/workitems?api-version=2019-06-17
  Waiting for completion of job 2149b727-53c7-4cec-b15c-ef3292790d64 on Ubuntu.1804.Amd64.Open
  Waiting for completion of job e585b358-f498-4a8c-85b5-e93a934fe9f5 on Ubuntu.1804.Amd64.Open
  Job 2149b727-53c7-4cec-b15c-ef3292790d64 on Ubuntu.1804.Amd64.Open is completed with 216 finished work items.
  Job e585b358-f498-4a8c-85b5-e93a934fe9f5 on Ubuntu.1804.Amd64.Open is completed with 216 finished work items.

We call it twice and it constructs the payload twice and sends the job twice.

[ViktorHofer]

@premun could you please open an issue for that?

[safern]

Actually, for this one, we send the Helix job twice. I don't think this is on purpose:

It is actually on purpose, once runs inside a browser and the other one under V8. That is the "multi-scenario" support that we added to sendtohelix.proj to be able to use one azure devops job to send multiple helix jobs with the same payload.

runtime/eng/pipelines/runtime.yml

Lines 284 to 286 in d1d6ab1

	scenarios:
	- normal
	- wasmtestonbrowser

[ViktorHofer]

Should they be invoked in parallel as presumably currently happening? Why do we restore the global tools when invoking sendtohelix.proj?

[safern]

If you look at the azure pipelines test name that proves this is the case as they contain the scenario in the name:

Stopping Azure Pipelines Test Run net6.0-Browser-Release-wasm-Mono_Release-normal-Ubuntu.1804.Amd64.Open
/__w/1/s/.packages/microsoft.dotnet.helix.sdk/6.0.0-beta.21101.7/tools/Microsoft.DotNet.Helix.Sdk.MultiQueue.targets(78,5): ...
...
Stopping Azure Pipelines Test Run net6.0-Browser-Release-wasm-Mono_Release-wasmtestonbrowser-Ubuntu.1804.Amd64.Open

[safern]

Should they be invoked in parallel as presumably currently happening? Why do we restore the global tools when invoking sendtohelix.proj?

I believe that yes they should be invoked in parallel.

If they are not invoked in parallel it would defeat the purpose of using one job for multiple helix runs as the second would need to wait for the first to be finished running tests before starting.

Note that all the workitem preparation and correlation payload is done sub-sequential, the only things that happen in parallel is invoking the helix SDK to send the helix job where the install of XHarness happen.

Why do we restore the global tools when invoking sendtohelix.proj?

That is part of the Helix.SDK when the tests use XHarness, they restore it to download xharness to include it as part of the payload. When we installed xharness as part of the test run on the helix machine we were restoring it ~250 times per helix job if the machines were not re-used and we were hitting throttling issues.

Maybe the improvement here is for the Helix.SDK to check if the tool (with the version it needs) is already installed just package it up as part of the payload and don't try to install it again.