Enable test logging for ProjectTemplate tests by BrennanConroy · Pull Request #26507 · dotnet/aspnetcore

BrennanConroy · 2020-10-01T19:58:44Z

Possible change to templates tests so we have log artifacts. Only applied it to a couple tests to show the idea first.

Pilchie

Should we consider targeting this for release/5.0 to aid diagnostics there?

BrennanConroy · 2020-10-01T23:36:39Z

Should we consider targeting this for release/5.0 to aid diagnostics there?

If I get general consensus that this is a good change/correct way to do it, then I can update the other tests and move it

BrennanConroy · 2020-10-05T18:58:18Z

I didn't add LoggedTest to Components and BlazorTemplates as they have other complex infrastructure that I am unfamiliar with. But I did get rid of the Xunit.TestFramework that they were using and moved them to the common one we use everywhere else.

BrennanConroy · 2020-10-06T17:33:36Z

Any feedback?

Tratcher · 2020-10-07T21:13:24Z

So the new logs are these ones?
Artifacts/Published/WIndows_Test_Template_Logs/ProjectTemplates.Test/net5.0/Templates.Test.EmptyWebTemplateTest/EmptyWebTemplateCSharp.log

[0.009s] [TestLifetime] [Information] Starting test EmptyWebTemplateCSharp at 2020-10-05T22:50:04
[33.740s] [Templates.Test.EmptyWebTemplateTest] [Information] ==> F:\workspace\_work\1\s\.dotnet\dotnet.exe new web --debug:custom-hive "F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\\Hives\67756e2a-e6ad-477d-85f4-81460bb72785\.templateengine" -o F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02 [F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\]
[35.603s] [Templates.Test.EmptyWebTemplateTest] [Information] The template "ASP.NET Core Empty" was created successfully.
[35.603s] [Templates.Test.EmptyWebTemplateTest] [Information] 
[35.606s] [Templates.Test.EmptyWebTemplateTest] [Information] Processing post-creation actions...
[35.606s] [Templates.Test.EmptyWebTemplateTest] [Information] Running 'dotnet restore' on F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02\AspNet.5zcfjn4rp02.csproj...
[36.810s] [Templates.Test.EmptyWebTemplateTest] [Information]   Determining projects to restore...
[37.335s] [Templates.Test.EmptyWebTemplateTest] [Information]   Restored F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02\AspNet.5zcfjn4rp02.csproj (in 179 ms).
[37.379s] [Templates.Test.EmptyWebTemplateTest] [Information] Restore succeeded.
[37.379s] [Templates.Test.EmptyWebTemplateTest] [Information] 
[37.503s] [Templates.Test.EmptyWebTemplateTest] [Information] Publishing ASP.NET Core application...
[37.504s] [Templates.Test.EmptyWebTemplateTest] [Information] ==> F:\workspace\_work\1\s\.dotnet\dotnet.exe publish --no-restore -c Release /bl  [F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02]
[38.183s] [Templates.Test.EmptyWebTemplateTest] [Information] Microsoft (R) Build Engine version 16.8.0-preview-20451-02+51a1071f8 for .NET
[38.183s] [Templates.Test.EmptyWebTemplateTest] [Information] Copyright (C) Microsoft Corporation. All rights reserved.
[38.183s] [Templates.Test.EmptyWebTemplateTest] [Information] 
[38.206s] [Templates.Test.EmptyWebTemplateTest] [Information] F:\workspace\_work\1\s\.dotnet\sdk\5.0.100-rc.1.20452.10\MSBuild.dll -maxcpucount -property:Configuration=Release -target:Publish -verbosity:m /bl .\AspNet.5zcfjn4rp02.csproj
[38.989s] [Templates.Test.EmptyWebTemplateTest] [Information]   You are using a preview version of .NET. See: https://aka.ms/dotnet-core-preview
[40.935s] [Templates.Test.EmptyWebTemplateTest] [Information]   AspNet.5zcfjn4rp02 -> F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02\bin\Release\net5.0\AspNet.5zcfjn4rp02.dll
[41.037s] [Templates.Test.EmptyWebTemplateTest] [Information]   AspNet.5zcfjn4rp02 -> F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02\bin\Release\net5.0\publish\
[41.144s] [Templates.Test.EmptyWebTemplateTest] [Information] Building ASP.NET Core application...
[41.144s] [Templates.Test.EmptyWebTemplateTest] [Information] ==> F:\workspace\_work\1\s\.dotnet\dotnet.exe build --no-restore -c Debug /bl  [F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02]
[41.464s] [Templates.Test.EmptyWebTemplateTest] [Information] Microsoft (R) Build Engine version 16.8.0-preview-20451-02+51a1071f8 for .NET
[41.464s] [Templates.Test.EmptyWebTemplateTest] [Information] Copyright (C) Microsoft Corporation. All rights reserved.
[41.464s] [Templates.Test.EmptyWebTemplateTest] [Information] 
[41.475s] [Templates.Test.EmptyWebTemplateTest] [Information] F:\workspace\_work\1\s\.dotnet\sdk\5.0.100-rc.1.20452.10\MSBuild.dll -consoleloggerparameters:Summary -maxcpucount -property:Configuration=Debug -verbosity:m /bl .\AspNet.5zcfjn4rp02.csproj
[42.074s] [Templates.Test.EmptyWebTemplateTest] [Information]   You are using a preview version of .NET. See: https://aka.ms/dotnet-core-preview
[43.297s] [Templates.Test.EmptyWebTemplateTest] [Information]   AspNet.5zcfjn4rp02 -> F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02\bin\Debug\net5.0\AspNet.5zcfjn4rp02.dll
[43.340s] [Templates.Test.EmptyWebTemplateTest] [Information] 
[43.340s] [Templates.Test.EmptyWebTemplateTest] [Information] Build succeeded.
[43.340s] [Templates.Test.EmptyWebTemplateTest] [Information]     0 Warning(s)
[43.340s] [Templates.Test.EmptyWebTemplateTest] [Information]     0 Error(s)
[43.340s] [Templates.Test.EmptyWebTemplateTest] [Information] 
[43.340s] [Templates.Test.EmptyWebTemplateTest] [Information] Time Elapsed 00:00:01.81
[43.408s] [Templates.Test.EmptyWebTemplateTest] [Information] Updating applicationUrl in launchSettings.json
[43.568s] [Templates.Test.EmptyWebTemplateTest] [Information] Running ASP.NET Core application...
[43.569s] [Templates.Test.EmptyWebTemplateTest] [Information] ==> F:\workspace\_work\1\s\.dotnet\dotnet.exe run --no-build [F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02]
[43.575s] [Templates.Test.EmptyWebTemplateTest] [Information] Waiting until ASP.NET application is accepting connections...
[44.569s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
[44.569s] [Templates.Test.EmptyWebTemplateTest] [Information]       Hosting starting
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.Hosting.Lifetime[0]
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information]       Now listening on: http://127.0.0.1:51371
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.Hosting.Lifetime[0]
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information]       Now listening on: https://127.0.0.1:51373
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Hosting.Diagnostics[0]
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information]       Loaded hosting startup assembly AspNet.5zcfjn4rp02
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.Hosting.Lifetime[0]
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information]       Application started. Press Ctrl+C to shut down.
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.Hosting.Lifetime[0]
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information]       Hosting environment: Development
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.Hosting.Lifetime[0]
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information]       Content root path: F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information]       Hosting started
[44.691s] [Templates.Test.EmptyWebTemplateTest] [Information] Detected that ASP.NET application is accepting connections on: http://127.0.0.1:51371
[44.692s] [Templates.Test.EmptyWebTemplateTest] [Information] Sending requests to http://localhost:51371
[46.394s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Server.Kestrel[39]
[46.394s] [Templates.Test.EmptyWebTemplateTest] [Information]       Connection id "0HM39G4DTLQHT" accepted.
[46.395s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Server.Kestrel[1]
[46.395s] [Templates.Test.EmptyWebTemplateTest] [Information]       Connection id "0HM39G4DTLQHT" started.
[46.424s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
[46.424s] [Templates.Test.EmptyWebTemplateTest] [Information]       Request starting HTTP/1.1 GET http://localhost:51371/ - -
[46.427s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[0]
[46.427s] [Templates.Test.EmptyWebTemplateTest] [Information]       Wildcard detected, all requests with hosts will be allowed.
[46.448s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]
[46.448s] [Templates.Test.EmptyWebTemplateTest] [Information]       1 candidate(s) found for the request path '/'
[46.448s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]
[46.448s] [Templates.Test.EmptyWebTemplateTest] [Information]       Request matched endpoint '/ HTTP: GET'
[46.449s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
[46.449s] [Templates.Test.EmptyWebTemplateTest] [Information]       Executing endpoint '/ HTTP: GET'
[46.452s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
[46.452s] [Templates.Test.EmptyWebTemplateTest] [Information]       Executed endpoint '/ HTTP: GET'
[46.452s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Server.Kestrel[9]
[46.452s] [Templates.Test.EmptyWebTemplateTest] [Information]       Connection id "0HM39G4DTLQHT" completed keep alive response.
[46.453s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
[46.453s] [Templates.Test.EmptyWebTemplateTest] [Information]       Request finished HTTP/1.1 GET http://localhost:51371/ - - - 200 - - 29.5899ms
[46.470s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets[6]
[46.471s] [Templates.Test.EmptyWebTemplateTest] [Information]       Connection id "0HM39G4DTLQHT" received FIN.
[46.736s] [Templates.Test.EmptyWebTemplateTest] [Information] Running ASP.NET Core application...
[46.740s] [Templates.Test.EmptyWebTemplateTest] [Information] ==> F:\workspace\_work\1\s\.dotnet\dotnet.exe exec F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02\bin\Release\net5.0\publish\AspNet.5zcfjn4rp02.dll [F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02\bin\Release\net5.0\publish]
[46.745s] [Templates.Test.EmptyWebTemplateTest] [Information] Waiting until ASP.NET application is accepting connections...
[46.978s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
[46.978s] [Templates.Test.EmptyWebTemplateTest] [Information]       Hosting starting
[47.062s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.Hosting.Lifetime[0]
[47.062s] [Templates.Test.EmptyWebTemplateTest] [Information]       Now listening on: http://127.0.0.1:51383
[47.062s] [Templates.Test.EmptyWebTemplateTest] [Information] Detected that ASP.NET application is accepting connections on: http://127.0.0.1:51383
[47.062s] [Templates.Test.EmptyWebTemplateTest] [Information] Sending requests to http://localhost:51383
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.Hosting.Lifetime[0]
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information]       Now listening on: https://127.0.0.1:51384
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Hosting.Diagnostics[0]
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information]       Loaded hosting startup assembly AspNet.5zcfjn4rp02
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.Hosting.Lifetime[0]
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information]       Application started. Press Ctrl+C to shut down.
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.Hosting.Lifetime[0]
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information]       Hosting environment: Production
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.Hosting.Lifetime[0]
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information]       Content root path: F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\net5.0\TestTemplates\AspNet.5zcfjn4rp02\bin\Release\net5.0\publish
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
[47.063s] [Templates.Test.EmptyWebTemplateTest] [Information]       Hosting started
[48.108s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Server.Kestrel[39]
[48.108s] [Templates.Test.EmptyWebTemplateTest] [Information]       Connection id "0HM39G4EE0BU9" accepted.
[48.109s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Server.Kestrel[1]
[48.109s] [Templates.Test.EmptyWebTemplateTest] [Information]       Connection id "0HM39G4EE0BU9" started.
[48.137s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
[48.137s] [Templates.Test.EmptyWebTemplateTest] [Information]       Request starting HTTP/1.1 GET http://localhost:51383/ - -
[48.140s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware[0]
[48.140s] [Templates.Test.EmptyWebTemplateTest] [Information]       Wildcard detected, all requests with hosts will be allowed.
[48.162s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Routing.Matching.DfaMatcher[1001]
[48.162s] [Templates.Test.EmptyWebTemplateTest] [Information]       1 candidate(s) found for the request path '/'
[48.162s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware[1]
[48.162s] [Templates.Test.EmptyWebTemplateTest] [Information]       Request matched endpoint '/ HTTP: GET'
[48.163s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
[48.163s] [Templates.Test.EmptyWebTemplateTest] [Information]       Executing endpoint '/ HTTP: GET'
[48.167s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
[48.167s] [Templates.Test.EmptyWebTemplateTest] [Information]       Executed endpoint '/ HTTP: GET'
[48.167s] [Templates.Test.EmptyWebTemplateTest] [Information] dbug: Microsoft.AspNetCore.Server.Kestrel[9]
[48.167s] [Templates.Test.EmptyWebTemplateTest] [Information]       Connection id "0HM39G4EE0BU9" completed keep alive response.
[48.167s] [Templates.Test.EmptyWebTemplateTest] [Information] info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
[48.167s] [Templates.Test.EmptyWebTemplateTest] [Information]       Request finished HTTP/1.1 GET http://localhost:51383/ - - - 200 - - 31.7592ms
[48.274s] [TestLifetime] [Information] Finished test EmptyWebTemplateCSharp in 48.2636882s

BrennanConroy · 2020-10-07T21:16:39Z

Yep, they didn't exist before.

BrennanConroy · 2020-10-07T21:35:25Z

@dotnet/aspnet-build please merge when available!

ghost added the area-mvc Includes: MVC, Actions and Controllers, Localization, CORS, most templates label Oct 1, 2020

BrennanConroy requested review from JunTaoLuo, Pilchie and pranavkm October 1, 2020 22:36

Pilchie approved these changes Oct 1, 2020

View reviewed changes

BrennanConroy added 4 commits October 5, 2020 15:16

Enable test logging for ProjectTemplate tests

56ea6cc

Add logging to templates

e454bc7

some updates

2937331

nullref

cfbb362

BrennanConroy force-pushed the brecon/templateLog branch from 2d4f326 to cfbb362 Compare October 5, 2020 22:20

BrennanConroy changed the base branch from master to release/5.0 October 5, 2020 22:20

BrennanConroy marked this pull request as ready for review October 5, 2020 22:20

BrennanConroy requested review from a team and SteveSandersonMS as code owners October 5, 2020 22:20

BrennanConroy added the tell-mode Indicates a PR which is being merged during tell-mode label Oct 5, 2020

BrennanConroy requested review from Tratcher and halter73 October 7, 2020 17:06

Tratcher approved these changes Oct 7, 2020

View reviewed changes

wtgodbe merged commit 5b6362f into release/5.0 Oct 7, 2020

wtgodbe deleted the brecon/templateLog branch October 7, 2020 21:37

BrennanConroy mentioned this pull request Oct 7, 2020

Add LoggedTest to Components E2E and Blazor template tests #26679

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Enable test logging for ProjectTemplate tests#26507

Enable test logging for ProjectTemplate tests#26507
wtgodbe merged 4 commits into
release/5.0from
brecon/templateLog

BrennanConroy commented Oct 1, 2020 •

edited

Loading

Uh oh!

Pilchie left a comment •

edited

Loading

Uh oh!

BrennanConroy commented Oct 1, 2020

Uh oh!

BrennanConroy commented Oct 5, 2020

Uh oh!

BrennanConroy commented Oct 6, 2020

Uh oh!

Tratcher commented Oct 7, 2020

Uh oh!

BrennanConroy commented Oct 7, 2020

Uh oh!

BrennanConroy commented Oct 7, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Conversation

BrennanConroy commented Oct 1, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Pilchie left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

BrennanConroy commented Oct 1, 2020

Uh oh!

BrennanConroy commented Oct 5, 2020

Uh oh!

BrennanConroy commented Oct 6, 2020

Uh oh!

Tratcher commented Oct 7, 2020

Uh oh!

BrennanConroy commented Oct 7, 2020

Uh oh!

BrennanConroy commented Oct 7, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

BrennanConroy commented Oct 1, 2020 •

edited

Loading

Pilchie left a comment •

edited

Loading