Proxy supplies logs with relevant info for each stage of the request

[MihaZupan]

Opening a new issue as discussion in #115 was unrelated.

[karelz]

Triage: We need to check that we are logging useful info about request progress and failures in YARP (E2E).

[luizfbicalho]

How can I enable logging on the yarp, I added this code but nothing happens.
I'm with preview 1.0.0-preview.9.21075.2

 services.AddLogging(builder => builder
              .AddConsole().AddDebug()
          );
            services.AddReverseProxy()
                .LoadFromConfig(Configuration.GetSection("ReverseProxy"));
            services.AddTelemetryListeners();

[Tratcher]

@luizfbicalho see
https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-5.0#logging-providers
https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-5.0#configure-logging

[luizfbicalho]

Sorry @Tratcher I didn't explain my point, this code returns me my log

 endpoints.MapReverseProxy(proxyPipeline =>
                {
                    proxyPipeline.Use(async (context, next) =>
                    {

                        var provider = context.RequestServices;
                        var logger = provider.GetService<ILogger<Startup>>();
                        logger.Log(LogLevel.Information, "TEST");

But I couldn't make the log from the requests on the other server to be logged, I have an error 500 in the proxy that I can't reproduce, and I would like to see all of the information that is going and coming back to find ot what is going on this request.

Thanks for the help

[karelz]

@MihaZupan plans to write docs about Telemetry in #676. The linked consumption sample may help?

[karelz]

@luizfbicalho if you have troubles with specific case, let's move it to separate issue. This is User Story describing the general capability, not troubleshooting specific bugs / shortcomings.

[Tratcher]

The log INFO: Microsoft.ReverseProxy.Service.Proxy.HttpProxy Proxying to "https://vmx0007223:9999/graphql" should include more fields like method, protocol version, version policy, content-length, etc. comparable to the ASP.NET event INFO: Microsoft.AspNetCore.Hosting.Diagnostics Request starting HTTP/2 POST https://vmx0007223:8443/api/graphql application/json 406
Do we need a matching log for the response, or is the ASP.NET log sufficient?
INFO: Microsoft.AspNetCore.Hosting.Diagnostics Request finished HTTP/2 POST https://vmx0007223:8443/api/graphql application/json 501 - 502 0 - 56.7773ms

[karelz]

Triage: We need to test few important scenarios and review what we log from them.

[samsp-msft]

With the output included in the default console log, and the samples for more detailed telemetry and metrics, IMHO we have this covered.
Removing the milestone so it gets shown in triage again.

[Tratcher]

@samsp-msft please run a few error scenarios and see if you get the logs you expect.

[samsp-msft]

Playing with this a bit more, I think in the default log we could be including more information about the destination request/response.

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 POST https://localhost:5001/test text/plain 55
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'minimumroute'
info: Yarp.ReverseProxy.Forwarder.HttpForwarder[9]
      Proxying to http://www.example.com/test
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'minimumroute'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 POST https://localhost:5001/test text/plain 55 - 404 445 text/html;+charset=utf-8 85.3726ms

What I could be considered missing is the destination IP, protocol version, protocol version policy.

The following should not change from the request: method, content size
The response content size and status code are reported by the proxy - assuming that the proxy hasn't changed them.

I suspect the main question is who needs the data and when? For general purpose logging - its probably sufficient.

However in the case that there is a problem, and the user is trying to determine what has gone wrong then its probably insufficient. In those cases having log entries that detail the request and response header stats would be useful. Ideally this would be a feature included in the proxy that can be turned on and off via configuration (which enables commandline and env variables) and possibly through a request header. It could be delivered via a sample, but seems like it would be better to be baked in as a standard module. It really needs to run after the transforms so is not readily insertable by the user.

[Tratcher]

What I could be considered missing is the destination IP, protocol version, protocol version policy.

The destination IP isn't available at the YARP layer, that's managed internally by SocketsHttpHandler.

The requested protocol version and policy make sense to add.

However in the case that there is a problem, and the user is trying to determine what has gone wrong then its probably insufficient. In those cases having log entries that detail the request and response header stats would be useful. Ideally this would be a feature included in the proxy that can be turned on and off via configuration (which enables commandline and env variables) and possibly through a request header. It could be delivered via a sample, but seems like it would be better to be baked in as a standard module. It really needs to run after the transforms so is not readily insertable by the user.

.NET 6 has a new logging middleware for this. Give it a try?
https://github.com/dotnet/aspnetcore/blob/05008201d4d5f29d5f348cc26b47b5e7e73fa410/src/Middleware/HttpLogging/samples/HttpLogging.Sample/Startup.cs#L27

[samsp-msft]

Now that the filtering list has been updated, the logging middleware has sufficient data. I am going to change this to a doc topic.