Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Create subcategories for better filtering Kestrel logs #31596

Merged
merged 3 commits into from
Apr 22, 2021

Conversation

fvoronin
Copy link
Contributor

@fvoronin fvoronin commented Apr 7, 2021

Splitting Kestrel logs into multiple subcategories from general "Microsoft.AspNetCore.Server.Kestrel":

  1. Microsoft.AspNetCore.Server.Kestrel (current category): ApplicationError, ConnectionHeadResponseBodyWrite, ApplicationNeverCompleted, RequestBodyStart, RequestBodyDone, RequestBodyNotEntirelyRead, RequestBodyDrainTimedOut, ResponseMinimumDataRateNotSatisfied, InvalidResponseHeaderRemoved, HeartbeatSlow.
  2. Microsoft.AspNetCore.Server.Kestrel.BadRequests: ConnectionBadRequest, RequestProcessingError, RequestBodyMinimumDataRateNotSatisfied.
  3. Microsoft.AspNetCore.Server.Kestrel.Connections: ConnectionAccepted, ConnectionStart, ConnectionStop, ConnectionPause, ConnectionResume, ConnectionKeepAlive, ConnectionRejected, ConnectionDisconnect, NotAllConnectionsClosedGracefully, NotAllConnectionsAborted, HeartbeatSlow, ApplicationAbortedConnection.
  4. Microsoft.AspNetCore.Server.Kestrel.Http2: Http2ConnectionError, Http2ConnectionClosing, Http2ConnectionClosed, Http2StreamError, Http2StreamResetAbort, HPackDecodingError, HPackEncodingError, Http2FrameReceived, Http2FrameSending, Http2MaxConcurrentStreamsReached.
  5. Microsoft.AspNetCore.Server.Kestrel.Http3: Http3ConnectionError, Http3ConnectionClosing, Http3ConnectionClosed, Http3StreamAbort, Http3FrameReceived, Http3FrameSending.

Fixes #30301

@ghost ghost added area-runtime community-contribution Indicates that the PR has been added by a community member labels Apr 7, 2021
@gfoidl gfoidl mentioned this pull request Apr 8, 2021
@davidfowl
Copy link
Member

One failing test:

[xUnit.net 00:00:04.14]     Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.HttpConnectionManagerTests.CriticalErrorLoggedIfApplicationDoesntComplete [FAIL]

@fvoronin
Copy link
Contributor Author

fvoronin commented Apr 8, 2021

One failing test:

[xUnit.net 00:00:04.14]     Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.HttpConnectionManagerTests.CriticalErrorLoggedIfApplicationDoesntComplete [FAIL]

Thanks.
Haha, i miss out that cause it's run #if !DEBUG.

@fvoronin
Copy link
Contributor Author

fvoronin commented Apr 8, 2021

Oh, i dont know why this test failed

[xUnit.net 00:00:28.41]     Microsoft.AspNetCore.Server.Kestrel.Core.Tests.Http3ConnectionTests.InboundStreams_CreateMultiple_ConnectionError(streamId: 3, name: "decoder") [FAIL]

It does not corelated with code changes in this PR.

@Tratcher
Copy link
Member

Tratcher commented Apr 8, 2021

The H3 tests are still new and a bit unstable, I've re-run them.

@davidfowl davidfowl added this to the 6.0-preview4 milestone Apr 8, 2021
@halter73
Copy link
Member

halter73 commented Apr 8, 2021

The same test failed on the second attempt. So it's either really flaky or something changed. I've started a third run to collect more data.

@halter73
Copy link
Member

halter73 commented Apr 8, 2021

Never mind. The same test didn't fail. It was ProjectTemplates tests failing on attempt 2 which are very flaky. I was looking at the new ".NET Helix Build Analysis" view. While it's super convenient, it doesn't appear to update on retries.

}

public virtual void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now)
{
_heartbeatSlow(_logger, now, heartbeatDuration, interval, null);
_heartbeatSlow(_connectionsLogger, now, heartbeatDuration, interval, null);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: While the heartbeat does loop over connections, this log is usually an indicator of threadpool starvation.

Suggested change
_heartbeatSlow(_connectionsLogger, now, heartbeatDuration, interval, null);
_heartbeatSlow(_generalLogger, now, heartbeatDuration, interval, null);

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Applied

Copy link
Member

@halter73 halter73 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks! This looks great.

…usually an indicator of threadpool starvation
@halter73 halter73 merged commit ca0c292 into dotnet:main Apr 22, 2021
@ghost ghost modified the milestones: 6.0-preview4, 6.0-preview5 Apr 22, 2021
@halter73
Copy link
Member

Thanks @fvoronin! (I also accidently put this in the commit message 🤣 )

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area-networking Includes servers, yarp, json patch, bedrock, websockets, http client factory, and http abstractions community-contribution Indicates that the PR has been added by a community member
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Create subcategories for better filtering Kestrel logs
5 participants