Skip to content

Commit eb06dd9

Browse files
authored
Update diagnosing-yarp-issues.md
1 parent 169eac0 commit eb06dd9

File tree

1 file changed

+68
-50
lines changed

1 file changed

+68
-50
lines changed

aspnetcore/fundamentals/servers/yarp/diagnosing-yarp-issues.md

Lines changed: 68 additions & 50 deletions
Original file line numberDiff line numberDiff line change
@@ -9,17 +9,17 @@ ms.topic: article
99
content_well_notification: AI-contribution
1010
ai-usage: ai-assisted
1111
---
12-
1312
# YARP Diagnosing YARP-based proxies
1413

1514
When using a reverse proxy, there is an additional hop from the client to the proxy, and then from the proxy to destination for things to go wrong. This topic should provide some hints and tips for how to debug and diagnose issues when they occur. It assumes that the proxy is already running, and so does not include problems at startup such as configuration errors.
1615

1716
## Logging
17+
1818
The first step to being able to tell what is going on with YARP is to turn on [logging](/aspnet/core/fundamentals/logging/#configure-logging). This is a configuration flag so can be changed on the fly. YARP is implemented as a middleware component for ASP.NET Core, so you need to enable logging for both YARP and ASP.NET to get the complete picture of what is going on.
1919

2020
By default ASP.NET will log to the console, and the configuration file can be used to control the level of logging.
2121

22-
```Json
22+
```json
2323
//Sets the Logging level for ASP.NET
2424
"Logging": {
2525
"LogLevel": {
@@ -34,38 +34,39 @@ By default ASP.NET will log to the console, and the configuration file can be us
3434

3535
You want logging information from the `Microsoft.AspNetCore.\*` and `Yarp.ReverseProxy.\*` providers. The preceding example emits `Information`-level events from both providers to the console. Changing the level to `Debug` shows additional entries. ASP.NET implements change detection for configuration files, so you can edit the `appsettings.json` file (or `appsettings.development.json` for the `Development` environment) while the project is running and observe changes to the log output.
3636

37-
> Note: Settings in the `appsettings.development.jso`n file override settings in `appsettings.json` when running in the `Development` environment, so make sure that if you are editing `appsettings.json` that the values aren't overridden.
37+
> [!NOTE]
38+
> Settings in the `appsettings.development.json` file override settings in `appsettings.json` when running in the `Development` environment, so make sure that if you are editing `appsettings.json` that the values aren't overridden.
3839
39-
### Understanding Log entries
40+
### Understanding log entries
4041

4142
The logging output is directly tied to the way that ASP.NET Core processes requests. It's important to realize that as middleware, YARP is relying on much of the ASP.NET functionality to process the requests, for example the following is for the processing of a request with "Debug" mode enabled:
4243

4344
| Level | Log Message | Description |
44-
| ----- | ----------- | ----------- |
45+
| --- | --- | --- |
4546
| dbug | Microsoft.AspNetCore.Server.Kestrel.Connections[39]<br>Connection id "0HMCD0JK7K51U" accepted.| Connections are independent of requests, so this is a new connection |
4647
| dbug | Microsoft.AspNetCore.Server.Kestrel.Connections[1]<br>Connection id "0HMCD0JK7K51U" started. | |
4748
| info | Microsoft.AspNetCore.Hosting.Diagnostics[1]<br>Request starting HTTP/1.1 GET http://localhost:5000/ - - | This is the incoming request to ASP.NET |
4849
| dbug | Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[0]<br>Wildcard detected, all requests with hosts will be allowed. | My configuration does not tie endpoints to specific hostnames |
4950
| dbug | Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]<br>1 candidate(s) found for the request path '/' | This shows what possible matches there are for the route |
50-
| dbug | Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1005]<br> Endpoint 'minimumroute' with route pattern '{\*\*catch-all}' is valid for the request path '/' | The minimum route from YARPs configuration has matched|
51-
| dbug | Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]<br> Request matched endpoint 'minimumroute' | |
52-
| info | Microsoft.AspNetCore.Routing.EndpointMiddleware[0]<br> Executing endpoint 'minimumroute' | |
53-
| info | Yarp.ReverseProxy.Forwarder.HttpForwarder[9]<br> Proxying to http://www.example.com/ | YARP is proxying the request to example.com |
54-
| info | Microsoft.AspNetCore.Routing.EndpointMiddleware[1]<br> Executed endpoint 'minimumroute' | |
55-
| dbug | Microsoft.AspNetCore.Server.Kestrel.Connections[9]<br> Connection id "0HMCD0JK7K51U" completed keep alive response. | The response has finished, but connection can be kept alive. |
51+
| dbug | Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1005]<br>Endpoint 'minimumroute' with route pattern '{\*\*catch-all}' is valid for the request path '/' | The minimum route from YARPs configuration has matched|
52+
| dbug | Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]<br>Request matched endpoint 'minimumroute' | |
53+
| info | Microsoft.AspNetCore.Routing.EndpointMiddleware[0]<br>Executing endpoint 'minimumroute' | |
54+
| info | Yarp.ReverseProxy.Forwarder.HttpForwarder[9]<br>Proxying to http://www.example.com/ | YARP is proxying the request to example.com |
55+
| info | Microsoft.AspNetCore.Routing.EndpointMiddleware[1]<br>Executed endpoint 'minimumroute' | |
56+
| dbug | Microsoft.AspNetCore.Server.Kestrel.Connections[9]<br>Connection id "0HMCD0JK7K51U" completed keep alive response. | The response has finished, but connection can be kept alive. |
5657
| info | Microsoft.AspNetCore.Hosting.Diagnostics[2]<br>Request finished HTTP/1.1 GET http://localhost:5000/ - - - 200 1256 text/html;+charset=utf-8 12.7797ms| The response completed with status code 200, responding with 1256 bytes as text/html in ~13ms. |
57-
| dbug | Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[6]<br> Connection id "0HMCD0JK7K51U" received FIN. | Diagnostic information about the connection to determine who closed it and how cleanly |
58-
| dbug | Microsoft.AspNetCore.Server.Kestrel.Connections[10]<br> Connection id "0HMCD0JK7K51U" disconnecting. | |
59-
| dbug | Microsoft.AspNetCore.Server.Kestrel.Connections[2]<br> Connection id "0HMCD0JK7K51U" stopped. | |
60-
| dbug | Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]<br> Connection id "0HMCD0JK7K51U" sending FIN because: "The Socket transport's send loop completed gracefully." | |
58+
| dbug | Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[6]<br>Connection id "0HMCD0JK7K51U" received FIN. | Diagnostic information about the connection to determine who closed it and how cleanly |
59+
| dbug | Microsoft.AspNetCore.Server.Kestrel.Connections[10]<br>Connection id "0HMCD0JK7K51U" disconnecting. | |
60+
| dbug | Microsoft.AspNetCore.Server.Kestrel.Connections[2]<br>Connection id "0HMCD0JK7K51U" stopped. | |
61+
| dbug | Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[7]<br>Connection id "0HMCD0JK7K51U" sending FIN because: "The Socket transport's send loop completed gracefully." | |
6162

6263
The above gives general information about the request and how it was processed.
6364

64-
### Using ASP.NET Request Logging
65+
### Using ASP.NET request logging
6566

66-
ASP.NET includes a middleware component that can be used to provide more details about the request and response. The `UseHttpLogging` component can be added to the request pipeline. It will add additional entries to the log detailing the incoming and outgoing request headers.
67+
ASP.NET includes a middleware component that can be used to provide more details about the request and response. The `UseHttpLogging` component can be added to the request pipeline, which adds additional entries to the log detailing the incoming and outgoing request headers.
6768

68-
``` C#
69+
```csharp
6970
app.UseHttpLogging();
7071
// Enable endpoint routing, required for the reverse proxy
7172
app.UseRouting();
@@ -75,7 +76,7 @@ app.MapReverseProxy();
7576

7677
For example:
7778

78-
```Console
79+
```console
7980
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
8081
Request:
8182
Protocol: HTTP/1.1
@@ -102,7 +103,7 @@ info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
102103
X-Cache: [Redacted]
103104
```
104105

105-
## Using Telemetry Events
106+
## Using telemetry events
106107

107108
We recommend reading [Networking telemetry in .NET](/dotnet/fundamentals/networking/telemetry/overview) as a primer on how to consume networking telemetry in .NET.
108109

@@ -111,58 +112,70 @@ The [Metrics sample](https://github.com/microsoft/reverse-proxy/tree/main/sample
111112
* `ForwarderTelemetryConsumer`
112113
* `HttpClientTelemetryConsumer`
113114

114-
To use either of these you create a class implementing a <!-- fix link -->`[telemetry interface](https://microsoft.github.io/reverse-proxy/api/Yarp.Telemetry.Consumption.html#interfaces)`, such as [`IForwarderTelemetryConsumer`](https://github.com/microsoft/reverse-proxy/blob/release/latest/src/TelemetryConsumption/Forwarder/IForwarderTelemetryConsumer.cs):
115+
To use either of these, create a class implementing a [`Yarp.Telemetry.Consumption` interface](xref:Yarp.Telemetry.Consumption#interfaces), such as <xref:Yarp.Telemetry.Consumption.IForwarderTelemetryConsumer>:
115116

116117
```C#
117118
public class ForwarderTelemetry : IForwarderTelemetryConsumer
118119
{
119120
/// Called before forwarding a request.
120121
public void OnForwarderStart(DateTime timestamp, string destinationPrefix)
121122
{
122-
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => OnForwarderStart :: Destination prefix: {destinationPrefix}");
123+
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => " +
124+
$"OnForwarderStart :: Destination prefix: {destinationPrefix}");
123125
}
124126

125127
/// Called after forwarding a request.
126128
public void OnForwarderStop(DateTime timestamp, int statusCode)
127129
{
128-
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => OnForwarderStop :: Status: {statusCode}");
130+
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => " +
131+
$"OnForwarderStop :: Status: {statusCode}");
129132
}
130133

131134
/// Called before <see cref="OnForwarderStop(DateTime, int)"/> if forwarding the request failed.
132135
public void OnForwarderFailed(DateTime timestamp, ForwarderError error)
133136
{
134-
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => OnForwarderFailed :: Error: {error.ToString()}");
137+
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => " +
138+
$"OnForwarderFailed :: Error: {error.ToString()}");
135139
}
136140

137141
/// Called when reaching a given stage of forwarding a request.
138142
public void OnForwarderStage(DateTime timestamp, ForwarderStage stage)
139143
{
140-
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => OnForwarderStage :: Stage: {stage.ToString()}");
144+
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => " +
145+
$"OnForwarderStage :: Stage: {stage.ToString()}");
141146
}
142147

143148
/// Called periodically while a content transfer is active.
144-
public void OnContentTransferring(DateTime timestamp, bool isRequest, long contentLength, long iops, TimeSpan readTime, TimeSpan writeTime)
149+
public void OnContentTransferring(DateTime timestamp, bool isRequest, long contentLength,
150+
long iops, TimeSpan readTime, TimeSpan writeTime)
145151
{
146-
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => OnContentTransferring :: Is request: {isRequest}, Content length: {contentLength}, IOps: {iops}, Read time: {readTime:s\\.fff}, Write time: {writeTime:s\\.fff}");
152+
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => " +
153+
$"OnContentTransferring :: Is request: {isRequest}, Content length: {contentLength}, " +
154+
$"IOps: {iops}, Read time: {readTime:s\\.fff}, Write time: {writeTime:s\\.fff}");
147155
}
148156

149157
/// Called after transferring the request or response content.
150-
public void OnContentTransferred(DateTime timestamp, bool isRequest, long contentLength, long iops, TimeSpan readTime, TimeSpan writeTime, TimeSpan firstReadTime)
158+
public void OnContentTransferred(DateTime timestamp, bool isRequest, long contentLength,
159+
long iops, TimeSpan readTime, TimeSpan writeTime, TimeSpan firstReadTime)
151160
{
152-
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => OnContentTransferred :: Is request: {isRequest}, Content length: {contentLength}, IOps: {iops}, Read time: {readTime:s\\.fff}, Write time: {writeTime:s\\.fff}");
161+
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => " +
162+
$"OnContentTransferred :: Is request: {isRequest}, Content length: {contentLength}, " +
163+
$"IOps: {iops}, Read time: {readTime:s\\.fff}, Write time: {writeTime:s\\.fff}");
153164
}
154165

155166
/// Called before forwarding a request from `ForwarderMiddleware`, therefore is not called for direct forwarding scenarios.
156-
public void OnForwarderInvoke(DateTime timestamp, string clusterId, string routeId, string destinationId)
167+
public void OnForwarderInvoke(DateTime timestamp, string clusterId, string routeId,
168+
string destinationId)
157169
{
158-
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => OnForwarderInvoke:: Cluster id: {clusterId}, Route Id: {routeId}, Destination: {destinationId}");
170+
Console.WriteLine($"Forwarder Telemetry [{timestamp:HH:mm:ss.fff}] => " +
171+
$"OnForwarderInvoke:: Cluster id: {clusterId}, Route Id: {routeId}, Destination: {destinationId}");
159172
}
160173
}
161174
```
162175

163-
And then register the class as part of services, for example:
176+
Tegister the class as part of services, for example:
164177

165-
```C#
178+
```csharp
166179
services.AddTelemetryConsumer<ForwarderTelemetry>();
167180

168181
// Add the reverse proxy to capability to the server
@@ -171,24 +184,28 @@ var proxyBuilder = services.AddReverseProxy();
171184
proxyBuilder.LoadFromConfig(Configuration.GetSection("ReverseProxy"));
172185
```
173186

174-
Then you will log details on each part of the request, for example:
187+
Details are logged on each part of the request, for example:
175188

176-
```Console
177-
Forwarder Telemetry [06:40:48.186] => OnForwarderInvoke:: Cluster id: minimumcluster, Route Id: minimumroute, Destination: example.com
178-
Forwarder Telemetry [06:41:00.269] => OnForwarderStart :: Destination prefix: http://www.example.com/
189+
```console
190+
Forwarder Telemetry [06:40:48.186] => OnForwarderInvoke::
191+
Cluster id: minimumcluster, Route Id: minimumroute, Destination: example.com
192+
Forwarder Telemetry [06:41:00.269] => OnForwarderStart ::
193+
Destination prefix: http://www.example.com/
179194
Forwarder Telemetry [06:41:00.298] => OnForwarderStage :: Stage: SendAsyncStart
180195
Forwarder Telemetry [06:41:00.507] => OnForwarderStage :: Stage: SendAsyncStop
181-
Forwarder Telemetry [06:41:00.530] => OnForwarderStage :: Stage: ResponseContentTransferStart
196+
Forwarder Telemetry [06:41:00.530] => OnForwarderStage :: Stage:
197+
ResponseContentTransferStart
182198
Forwarder Telemetry [06:41:03.655] => OnForwarderStop :: Status: 200
183199
```
184200

185-
The events for Telemetry are fired as they occur, so you can [fish out the HttpContext](/aspnet/core/fundamentals/http-context#use-httpcontext-from-custom-components) and the YARP feature from it:
201+
The events for telemetry are fired as they occur, so you can [obtain the `HttpContext`](/aspnet/core/fundamentals/http-context#use-httpcontext-from-custom-components) and the YARP feature from it:
186202

187-
``` C#
203+
```csharp
188204
services.AddTelemetryConsumer<ForwarderTelemetry>();
189205
services.AddHttpContextAccessor();
190206
...
191-
public void OnForwarderInvoke(DateTime timestamp, string clusterId, string routeId, string destinationId)
207+
public void OnForwarderInvoke(DateTime timestamp, string clusterId, string routeId,
208+
string destinationId)
192209
{
193210
var context = new HttpContextAccessor().HttpContext;
194211
var YarpFeature = context.GetReverseProxyFeature();
@@ -204,7 +221,7 @@ public void OnForwarderInvoke(DateTime timestamp, string clusterId, string route
204221

205222
Another way to inspect the state for requests is to insert additional middleware into the request pipeline. You can insert between the other stages to see the state of the request.
206223

207-
```C#
224+
```csharp
208225
// We can customize the proxy pipeline and add/remove/replace steps
209226
app.MapReverseProxy(proxyPipeline =>
210227
{
@@ -234,18 +251,19 @@ public Task MyCustomProxyStep(HttpContext context, Func<Task> next)
234251

235252
You can also use [ASP.NET middleware](/aspnet/core/fundamentals/middleware/write) within Configure that will enable you to inspect the request before the proxy pipeline.
236253

237-
> **Note:** The proxy will stream the response from the destination server back to the client, so the response headers and body are not readily accessible via middleware.
254+
> [!NOTE]
255+
> The proxy streams the response from the destination server back to the client, so the response headers and body aren't readily accessible via middleware.
238256
239257
## Using the debugger
240258

241-
A debugger, such as Visual Studio can be attached to the proxy process. However, unless you have existing middleware, there is not a good place in the app code to break and inspect the state of the request. Therefore the debugger is best used in conjunction with one of the techniques above so that you have distinct places to insert breakpoints etc.
259+
A debugger, such as Visual Studio, can be attached to the proxy process. However, unless you have existing middleware, there isn't a good place in the app code to break and inspect the state of the request. Therefore, the debugger is best used in conjunction with one of the preceding techniques so that you have distinct places to insert breakpoints.
242260

243-
## Network Tracing
261+
## Network tracing
244262

245-
It can be attractive to use network tracing tools like [Fiddler](https://www.telerik.com/fiddler) or [Wireshark](https://www.wireshark.org/) to try to monitor what is happening either side of the proxy. However there are some gotchas to using both tools.
263+
It can be attractive to use network tracing tools like [Fiddler](https://www.telerik.com/fiddler) or [Wireshark](https://www.wireshark.org/) to try to monitor what's happening either side of the proxy. However, be cautious using both tools:
246264

247-
- Fiddler registers itself as a proxy and relies on applications using the default proxy to be able to monitor traffic. This works for inbound traffic from a browser to YARP, but will not capture the outbound requests as YARP is configured to not use the proxy settings for outbound traffic.
248-
- On windows Wireshark uses Npcap to capture packet data for network traffic, so it will capture both inbound and outbound traffic, and can be used to monitor HTTP traffic. Wireshark works out of the box for HTTP traffic.
249-
- HTTPS traffic is encrypted, and so is not automatically decryptable by network monitoring tools. Each tool has workarounds that may enable traffic to be monitored, but they require hacking around with certificates and trust relationships. Because YARP is making outbound requests, techniques for tricking browsers do not apply to the YARP process.
265+
* Fiddler registers itself as a proxy and relies on apps using the default proxy to be able to monitor traffic. This works for inbound traffic from a browser to YARP but won't capture the outbound requests, as YARP is configured to not use the proxy settings for outbound traffic.
266+
* On Windows, Wireshark uses Npcap to capture packet data for network traffic, so it captures both inbound and outbound traffic and can be used to monitor HTTP traffic.
267+
* HTTPS traffic is encrypted and isn't automatically decryptable by network monitoring tools. Each tool has workarounds that may enable traffic to be monitored, but they require risky use of certificates and changes to trust relationships. Because YARP is making outbound requests, techniques for tricking browsers don't apply to the YARP process.
250268

251-
The protocol choice for outbound traffic is made based on the destination URL in the cluster configuration. If traffic monitoring is being used for diagnostics then, if possible, changing the outbound URLs to "http://" may be simplest approach to enable the monitoring tools to work, provided the issues being diagnosed are not transport protocol related.
269+
The protocol choice for outbound traffic is made based on the destination URL in the cluster configuration. If traffic monitoring is used for diagnostics, changing the outbound URLs to `http://`, if possible, may be the simplest approach to enable the monitoring tools to work, provided the issues being diagnosed aren't transport protocol related.

0 commit comments

Comments
 (0)