dotnet / dotnet/sdk

MSBuild server discards the build telemetry event; make telemetry testable

Open
#55,749 6 comments 0 reactions 1 assignee Claimed by @JanProvaznik View on GitHub
Area-Telemetry cookie Task Test Debt
Dominant language
C#
Stars
3.2k
Forks
1.3k
PR merge metrics
PR metrics pending

Description

# Summary

The MSBuild server discards the `dotnet/cli/msbuild/build` telemetry event. PR #55582 did not correct this error. I verified this condition with an SDK build that contains that PR.

This issue has two parts:

| Part | Result |
|---|---|
| 1 | The telemetry is correct when the MSBuild server is on. |
| 2 | A test finds this class of error. A contributor gets a signal to test each new event. |

Part 1 is a defect. Part 2 prevents the next defect of the same type.

# Part 1: Correct the telemetry when the server is on

## The measurement

I used two SDK builds. One build is before PR #55582. The other build is after it.

| SDK | Build date | Contains PR #55582 |
|---|---|---|
| `11.0.100-preview.7.26357.101` | 2026-07-07 | no |
| `11.0.100-rc.1.26411.119` | 2026-08-11 | yes |

I confirmed the presence of the correction in the second build. The `dotnet.dll` file of that SDK contains the members `OnBuildStarted`, `StopActivity`, `_initializedTelemetryClient`, and `WaitForPendingEvents`. PR #55582 added each of these members.

The collector is the Aspire dashboard, version 13.4.6:

```
dotnet tool install -g Aspire.Cli --version 13.4.6

aspire dashboard run --frontend-url http://127.0.0.1:18890 ^
--otlp-http-url http://127.0.0.1:14320 ^
--allow-anonymous --non-interactive --nologo
```

Each trial used these steps:

1. Run `dotnet build-server shutdown`. This step removes each MSBuild process of a previous trial.
2. Run `dotnet build --no-incremental` with the variables below.
3. Wait for the export operation. Then read `GET /api/telemetry/spans?limit=1000`.

```
DOTNET_CLI_TELEMETRY_OPTOUT=false
DOTNET_CLI_TELEMETRY_ENABLE_EXPORTER=1
OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:14320
OTEL_EXPORTER_OTLP_PROTOCOL=http/protobuf
DOTNET_CLI_TELEMETRY_SHUTDOWN_TIMEOUT_MS=15000
```

**The result with the SDK that contains PR #55582:**

| Trial | `dotnet/cli/msbuild/build` |
|---|---|
| `MSBUILDUSESERVER=0` | **1** |
| `MSBUILDUSESERVER=1` | **0** |

The control: in the trial with the server, three conditions were true. The build returned exit code 0. An MSBuild server process was present after the build. The events `dotnet/cli/toplevelparser/command`, `dotnet/cli/sublevelparser/command`, and `dotnet/cli/command/finish` arrived over the same connection. Thus the export operation is correct and the network is correct. Only the build event is absent.

## The cause

The `TelemetryClient.TrackEventTask` method attaches each event to the current activity:

```csharp
var @event = new ActivityEvent($"dotnet/cli/{eventName}", tags: MakeTags(properties));
Activity.Current?.AddEvent(@event);
```

If `Activity.Current` is null, the `?.` operator discards the event.

PR #55582 added an activity for each build. `MSBuildLogger.OnBuildStarted` starts this activity. `MSBuildLogger.OnBuildFinished` stops it.

But MSBuild sends the build event **after** the `BuildFinished` event. The `BuildManager.cs` file shows this sequence:

| Line | Operation |
|---|---|
| 1204 | `loggingService.LogBuildFinished(_overallBuildSuccess)` |
| 1230 | `loggingService.LogTelemetry(buildEventContext: null, _buildTelemetry.EventName, ...)` |

Thus this sequence occurs:

1. `LogBuildFinished` sends `BuildFinished`.
2. `MSBuildLogger.OnBuildFinished` calls `StopActivity`. The activity of the build stops.
3. `LogTelemetry` sends the build event. The activity is not present now.

The behavior after step 2 is different in each host:

- **In the CLI process** the activity has a parent activity in the same process. After the stop operation, `Activity.Current` is the parent activity. Thus the event goes to the parent activity.
- **In the MSBuild server process** the activity has no parent activity in the same process. Its parent is a remote context. After the stop operation, `Activity.Current` is null. Thus the code discards the event.

## The evidence for this cause

The exported data of the trial without the server shows the two activities. The build event is not on the activity of the build. It is on the parent activity:

```
SPAN 'invocation'
- dotnet/cli/msbuild/build <- the build event is on the PARENT
SPAN 'msbuild' <- the activity that PR #55582 adds
- dotnet/cli/msbuild/loggingConfiguration
- dotnet/cli/msbuild/targetframeworkeval
- dotnet/cli/msbuild/targetframeworkeval
- dotnet/cli/msbuild/build/tasks/taskfactory
- dotnet/cli/msbuild/build/tasks
```

The other MSBuild events are on the `msbuild` activity. MSBuild sends these events during the build. Thus the activity is present for them.

Only the build event is on the parent activity. This position shows that the activity was already stopped when the build event arrived.

The CLI process has a parent activity, thus the event survives. The server process has no parent activity, thus the event does not survive. This difference explains each measurement above.

## Two results of this cause

1. **The server discards the build event.** This result is the defect in this issue.
2. **The CLI process puts the build event on the wrong activity.** The event is on `invocation` and not on `msbuild`. A correction of the cause also corrects this condition.

## Proposed correction

The activity of the build must be present when the build event arrives. Use one of these three methods:

1. **Stop the activity later.** Move `StopActivity` from `OnBuildFinished` to `Shutdown`. MSBuild calls `Shutdown` after each telemetry event.
2. **Add the event to a known activity.** Give the retained activity to `TrackEventTask` instead of `Activity.Current`.
3. **Send the build event before `BuildFinished` in MSBuild.** This method needs a change in the MSBuild repository. The other two methods need a change only in this repository.

Method 1 is the smallest change. Confirm that `Activity.Current` is the correct activity in `Shutdown`. The measurement above gives evidence for this condition. The build event went to the parent of the stopped activity. Thus the async context of the telemetry event is the same context.

# Part 2: Make the telemetry testable

No test finds the defect above. Three test methods exist today, and each one is successful when the defect is present.

**`FakeTelemetry`** (`test/dotnet.Tests/CommandTests/MSBuild/FakeTelemetry.cs`) shows that the logger called a method. It does not show that the process sent data.

**The tests in PR #55582** examine the parent of the activity. They use a synthetic `IEventSource`. They do not start a build. They do not start a server. They also do not examine the sequence of `BuildFinished` and the build event, thus they did not find the defect that remains.

**The disk log** (`DOTNET_CLI_TELEMETRY_LOG_PATH`) uses `AddInMemoryExporter(s_activities)`. The product uses `AddOtlpExporter` or `AddAzureMonitorTraceExporter`.

## Item 2.1: A telemetry test harness

Do not write a collector. The Aspire dashboard receives OTLP and gives a query API. Thus this team owns fewer parts. I verified each step of this method with the commands in part 1.

Create `test/dotnet.Tests/TelemetryTests/TelemetryCollectorFixture.cs`. The class does these operations:

1. It starts the Aspire dashboard as a child process. It uses `--allow-anonymous`, thus a test needs no API key.
2. It selects a free port for the frontend and a free port for OTLP. Two tests in parallel then use different ports.
3. It gives the OTLP endpoint address to the test.
4. It reads `GET /api/telemetry/spans` and returns the spans and their events.
5. It stops the dashboard at the end of the test class.

The response is OTLP JSON. `System.Text.Json` reads it. The `events` array of each span contains a `name` and an `attributes` array. This structure is the structure that the SDK sends. Thus a test examines the event name, each tag name, and **the activity of each event**. A decoder for the protobuf format is not necessary.

The test needs the activity of each event, because the defect in part 1 is a wrong activity. A harness that returns only a list of event names cannot find this defect.

Give the fixture this API:

```csharp
IReadOnlyList spans = await fixture.GetSpansAsync();
CollectedSpan msbuild = spans.Single(s => s.Name == "msbuild");
msbuild.Events.Should().Contain(e => e.Name == "dotnet/cli/msbuild/build");
```

Use the `PersistentStorageTelemetryE2ETests.cs` file as the example for the child process. Use `SdkTest`, `TestAssetsManager`, and `DotnetCommand` in the same manner.

These tests do not operate on a source-build leg. Thus the acquisition of the tool is acceptable. Exclude these tests from each leg that has no network access.

## Item 2.2: Tests for each host

Create `test/dotnet.Tests/TelemetryTests/TelemetryHostMatrixTests.cs`.

Use a matrix of the hosts. A list of conditions becomes old. A matrix shows which host has no test.

| Host | Environment | The test examines this |
|---|---|---|
| MSBuild server, cold start | default settings, no server operates | One `dotnet/cli/msbuild/build` event on the `msbuild` activity. `InitialMSBuildServerState` is `cold`. |
| MSBuild server, hot start | default settings, second build | The same conditions. `InitialMSBuildServerState` is `hot`. Not zero events. Not two events. |
| In process | `MSBUILDUSESERVER=0` | One event on the `msbuild` activity. `InitialMSBuildServerState` is absent. |
| Fall back to in process | a condition that stops the server | One event. `ServerFallbackReason` has a value. |
| Opt out | `DOTNET_CLI_TELEMETRY_OPTOUT=1` | Zero events. |

In .NET 11 the server is the default. Thus a test that sets `MSBUILDUSESERVER` manually does not test the path that most customers use. Use the default settings for the first two rows.

Assert the activity of the event, and not only the presence of the event. The in-process row is successful today, but the event is on the wrong activity. An assertion on the activity finds this condition also.

### Two conditions from the measurement

These two conditions are necessary. Without them a test gives a false result.

**1. Run `dotnet build-server shutdown` before each trial.** An MSBuild process of a previous trial stays in memory. This process keeps the environment of its own trial. Thus it sends the telemetry to the wrong address, or it sends nothing. My first trials gave a false result for this reason.

**2. Examine a control event in the same trial.** A build sends `dotnet/cli/toplevelparser/command` and `dotnet/cli/command/finish` from the CLI process. Assert that these events are present. This assertion separates two conditions:

- The build did not operate, or the export did not operate. Then the control events are also absent.
- The build operated and the export operated, but the product discarded the build event. Then the control events are present.

The second condition is the defect in part 1. Without the control, a test cannot show the difference.

## Item 2.3: A contract file and a CI gate

This item tells the contributors to test their new events.

Today a contributor gets no signal. The `documentation/project-docs/telemetry.md` file says: "Ensure that all telemetry events and properties are accurately documented". This is a convention. No code makes this necessary.

Use the `Verify.MSTest` package. This repository already references it in `test/dotnet.Tests/dotnet.Tests.csproj`. The `test/dotnet.Tests/CommandTests/Test/snapshots/MTPHelpSnapshotTests.VerifyMTPHelpOutput.verified.txt` file is an example of a snapshot.

Create `test/dotnet.Tests/TelemetryTests/TelemetryContractTests.cs` and its snapshot file. The test uses the harness of item 2.1. The snapshot contains each activity, each event name, and each tag name in sequence:

```
activity: msbuild
dotnet/cli/msbuild/build
BuildCheckEnabled
BuildEngineHost
BuildSuccess
BuildTarget
InitialMSBuildServerState
ProjectPath
ServerEnableReason
ServerFallbackReason
dotnet/cli/msbuild/loggingConfiguration
ConsoleLogger
TerminalLogger
```

The test removes the values, because a value is not stable. Then `Verify` compares the result with the snapshot file.

The snapshot contains the activity of each event. Thus a change of the activity also causes a failure.

`MSBuildLogger.cs` declares 16 constants with the `EventName` suffix. Add a test that reads these constants with reflection and compares them with the contract file. This check finds an event that no test condition sends.

### The conditions of failure

Each message must tell the contributor the next action:

| Condition | The message |
|---|---|
| The code declares an event. The contract file does not contain it. | "The event `dotnet/cli/foo` is not in the contract file. Add a test condition that sends this event. Then accept the new snapshot." |
| The contract file contains an event. No test sends it. | "No test sends the event `dotnet/cli/foo`. Add a test condition, or remove the event from the contract file." |
| A tag name or its letter case changed. | "The tag `BuildSuccess` changed to `buildSuccess`. This change stops the queries in the backend. Confirm that this change is necessary." |
| An event moved to a different activity. | "The event `dotnet/cli/msbuild/build` moved from the activity `msbuild` to the activity `invocation`. Confirm that this change is necessary." |

### The documentation

Add a section to `documentation/project-docs/telemetry.md`. Give this instruction to a contributor who adds an event:

1. Add the event name as a constant.
2. Add a test condition to `TelemetryHostMatrixTests` that sends the event.
3. Run the tests. Accept the new snapshot file.
4. Add the event to the table in this document.

# Optional: Make the error visible in the code

The items above examine the known events and the known hosts. This item protects the hosts that we do not know today. The AOT CLI and `dotnet watch` are examples.

Change `TrackEventTask`. Do one of these two operations:

- Write a diagnostic message when no current activity is present. Use `Debug.Fail` in the debug build.
- Let `TelemetryClient` start its own activity when no current activity is present.

The second operation also corrects the defect in part 1 for each host.

# Acceptance criteria

**Part 1**

- [ ] The activity of the build is present when the build event arrives.
- [ ] A build with the MSBuild server sends one `dotnet/cli/msbuild/build` event.
- [ ] The build event is on the `msbuild` activity, and not on the parent activity.
- [ ] The tags of the event contain `InitialMSBuildServerState`.

**Part 2, item 2.1**

- [ ] `TelemetryCollectorFixture` starts the Aspire dashboard and stops it. It uses free ports.
- [ ] It returns the spans, their events, and the tags of each event.
- [ ] It adds no package reference to the product or to the test project.

**Part 2, item 2.2**

- [ ] `TelemetryHostMatrixTests` contains each row of the table in item 2.2.
- [ ] Each trial runs `dotnet build-server shutdown` first.
- [ ] Each trial asserts a control event from the CLI process.
- [ ] Each trial asserts the activity of the build event.
- [ ] Remove the correction of part 1. Then the two server rows must fail. The other rows must stay successful. This criterion shows that the tests find the defect.

**Part 2, item 2.3**

- [ ] The contract snapshot file exists. It contains the activities, the events, and their tags.
- [ ] A new event without a contract entry causes a failure. The message gives the next action.
- [ ] A changed tag name causes a failure.
- [ ] An event on a different activity causes a failure.
- [ ] `telemetry.md` contains the four steps for a contributor.

# Related items

- PR #55582 adds an activity for each build. It is a necessary step. But it does not correct the defect, because it stops the activity before the build event arrives.
- PR #53181 and commit `9e81efe746` contain the OTel migration. This migration made the delivery of each event dependent on `Activity.Current`.
- PR #55231 makes the MSBuild server the default for `dotnet build` in .NET 11. Thus each build of a customer now uses the host that discards the event.
- PR #55211 changes the exporter to a persist-then-drain design. It also has no end-to-end test.

# Notes

Do not remove `TelemetryDiskLogger`. It is useful for local diagnosis. But it must not be the only test of the real output.

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.