Skip to content

[Helix] Better logging (flaky tests, logged tests) #18274

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

Merged
merged 18 commits into from
Jan 21, 2020
Merged

[Helix] Better logging (flaky tests, logged tests) #18274

merged 18 commits into from
Jan 21, 2020

Conversation

HaoK
Copy link
Member

@HaoK HaoK commented Jan 10, 2020

No description provided.

@ghost ghost added the area-infrastructure Includes: MSBuild projects/targets, build scripts, CI, Installers and shared framework label Jan 10, 2020
@HaoK HaoK changed the title See what happens when logging tests are turned on [Helix] See what happens when logging tests are turned on Jan 10, 2020
@dougbu
Copy link
Contributor

dougbu commented Jan 15, 2020

Please add @dotnet/aspnet-build as a reviewer when this is ready

@jkotalik
Copy link
Contributor

@HaoK if you could take a look into where I can put logs that would be picked up by azdo, that'd be useful. If we need to talk with helix folks as well.

@HaoK
Copy link
Member Author

HaoK commented Jan 15, 2020

@jkotalik yup, I see that the directory is there now:

drwxr-xr-x 3 helixbot helixbot 4096 Jan 15 04:48 Microsoft.AspNetCore.WebSockets.Tests

It looks like they are already searching for .log files to automatically upload, so maybe we just need to place them where they are scanning:

Searching '/datadisks/disk1/work/BC440A74/w/9A920888/e/..' for log files
Found log '/datadisks/disk1/work/BC440A74/w/9A920888/e/../console.23756920.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-1ae652f9e3c94aa9af/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/console.23756920.log?sv=2018-03-28&sr=c&sig=tGRSirhthMg08skFgq%2BmRUghruJIx4m6BUbisttiLvM%3D&se=2020-01-25T04%3A32%3A39Z&sp=rl'
Generated log list: <ul><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-1ae652f9e3c94aa9af/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/console.23756920.log?sv=2018-03-28&sr=c&sig=tGRSirhthMg08skFgq%2BmRUghruJIx4m6BUbisttiLvM%3D&se=2020-01-25T04%3A32%3A39Z&sp=rl' target='_blank'>console.23756920.log</a></li></ul>
Searching '/datadisks/disk1/work/BC440A74/w/9A920888/e' for test results files
Found results file /datadisks/disk1/work/BC440A74/w/9A920888/e/TestResults/_c001MJ0_2020-01-15_04_48_15.trx with format trx
Worker 0: uploaded 35 results

@jkotalik
Copy link
Contributor

Alright, who should we contact in Helix for this issue?

@dougbu
Copy link
Contributor

dougbu commented Jan 15, 2020

@jkotalik which issue? Helix itself has had a few problems over the last couple of days. But, moving files we want into the expected location seems reasonable.

@jkotalik
Copy link
Contributor

@dougbu unrelated to outages. We are specifically trying to find a location to put log files where they would be uploaded to azdo and correlated with the test names themselves.

@dougbu
Copy link
Contributor

dougbu commented Jan 15, 2020

The console logs are associated w/ the tests automatically. If we want to upload more, I believe placing additional files in the same location as those logs is the correct approach.

@MattGal is there a variable pointing to the per-test upload location? Anything else we should be aware of?

@MattGal
Copy link
Member

MattGal commented Jan 15, 2020

@doug

The console logs are associated w/ the tests automatically. If we want to upload more, I believe placing additional files in the same location as those logs is the correct approach.

@MattGal is there a variable pointing to the per-test upload location? Anything else we should be aware of?

Yes put them in $HELIX_WORKITEM_UPLOAD_ROOT / %HELIX_WORKITEM_UPLOAD_ROOT% and read back via the files API.

@jkotalik
Copy link
Contributor

Is $HELIX_WORKITEM_UPLOAD_ROOT only defined on the helix machine or are they on the azdo machine that builds the runtime? The problem we are running into is we'd define a folder to write logs to at build time on the azdo machine which is then sent to helix. This folder we define would need to be $HELIX_WORKITEM_UPLOAD_ROOT. Otherwise, we may need to hard code it.

Also, where is HELIX_WORKITEM_UPLOAD_ROOT defined? I looked in arcade and didn't see anything.

@dougbu
Copy link
Contributor

dougbu commented Jan 16, 2020

read back via the files API

  1. which "files API"?
  2. is there a shortcut approach to get the files we want into an AzDO artifact or automatically linked in the Tests tab?

@HaoK
Copy link
Member Author

HaoK commented Jan 16, 2020

I think something like the following should work, we just output the files into /logs/, and then add a copy /logs/* to upload root as part of our helix runtests bootstrapping script. @MattGal would this result in these files showing up alongside the worker console log in the attachements in azdo if a test fails? I think this would be a sufficient starting point.

@HaoK
Copy link
Member Author

HaoK commented Jan 16, 2020

Yay, almost there now, the files show up in the attachments

https://dev.azure.com/dnceng/public/_build/results?buildId=486699&view=ms.vss-test-web.build-test-results-tab&runId=15484896&resultId=100392&paneView=attachments

But clicking through to them doesn't result in anything, so maybe they aren't being uploaded properly @MattGal any ideas?

Here's the releveant console log output it found the logs, but the links don't go through properly

Searching '/datadisks/disk1/work/B56509B9/w/AB37097F/e/..' for log files
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../OriginIsValidatedForWebSocketRequests-OK-System.String[].log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-OK-System.String[].log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../SendMediumData_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendMediumData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../OriginIsValidatedForWebSocketRequests-OK-null.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-OK-null.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../CloseFromCloseReceived_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/CloseFromCloseReceived_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../SendLongData_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendLongData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../NegotiateSubProtocol_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/NegotiateSubProtocol_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../CloseFromCloseSent_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/CloseFromCloseSent_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../OriginIsValidatedForWebSocketRequests-Forbidden-System.String[].log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-Forbidden-System.String[].log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../ReceiveMediumData_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/ReceiveMediumData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../ReceiveShortData_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/ReceiveShortData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../console.d302a071.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/console.d302a071.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../OriginIsValidatedForWebSocketRequests-Forbidden-System.String[].0.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-Forbidden-System.String[].0.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../ReceiveClose_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/ReceiveClose_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../SendEmptyData_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendEmptyData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../Connect_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/Connect_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../ReceiveLongData.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/ReceiveLongData.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../OriginIsValidatedForWebSocketRequests-OK-System.String[].2.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-OK-System.String[].2.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../SendClose_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendClose_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../OriginIsNotValidatedForNonWebSocketRequests.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsNotValidatedForNonWebSocketRequests.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../SendFragmentedData_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendFragmentedData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../CloseFromOpen_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/CloseFromOpen_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../global.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/global.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../SendShortData_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendShortData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../OriginIsValidatedForWebSocketRequests-OK-System.String[].0.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-OK-System.String[].0.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../OriginIsValidatedForWebSocketRequests-OK-System.String[].1.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-OK-System.String[].1.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../ReceiveFragmentedData_Success.log'
Uri 'https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/ReceiveFragmentedData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl'
Generated log list: <ul><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-OK-System.String[].log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>OriginIsValidatedForWebSocketRequests-OK-System.String[].log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendMediumData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>SendMediumData_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-OK-null.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>OriginIsValidatedForWebSocketRequests-OK-null.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/CloseFromCloseReceived_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>CloseFromCloseReceived_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendLongData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>SendLongData_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/NegotiateSubProtocol_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>NegotiateSubProtocol_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/CloseFromCloseSent_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>CloseFromCloseSent_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-Forbidden-System.String[].log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>OriginIsValidatedForWebSocketRequests-Forbidden-System.String[].log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/ReceiveMediumData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>ReceiveMediumData_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/ReceiveShortData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>ReceiveShortData_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/console.d302a071.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>console.d302a071.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-Forbidden-System.String[].0.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>OriginIsValidatedForWebSocketRequests-Forbidden-System.String[].0.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/ReceiveClose_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>ReceiveClose_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendEmptyData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>SendEmptyData_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/Connect_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>Connect_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/ReceiveLongData.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>ReceiveLongData.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-OK-System.String[].2.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>OriginIsValidatedForWebSocketRequests-OK-System.String[].2.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendClose_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>SendClose_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsNotValidatedForNonWebSocketRequests.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>OriginIsNotValidatedForNonWebSocketRequests.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendFragmentedData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>SendFragmentedData_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/CloseFromOpen_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>CloseFromOpen_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/global.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>global.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/SendShortData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>SendShortData_Success.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-OK-System.String[].0.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>OriginIsValidatedForWebSocketRequests-OK-System.String[].0.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/OriginIsValidatedForWebSocketRequests-OK-System.String[].1.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>OriginIsValidatedForWebSocketRequests-OK-System.String[].1.log</a></li><li><a href='https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-18274-merge-b024faca7c3c45c382/Microsoft.AspNetCore.WebSockets.Tests-netcoreapp5.0/ReceiveFragmentedData_Success.log?sv=2018-03-28&sr=c&sig=TtkZOjDp0OKVEWLev8rHCHOiKbOBIUhK6TN%2F3YOFLO0%3D&se=2020-01-26T20%3A56%3A57Z&sp=rl' target='_blank'>ReceiveFragmentedData_Success.log</a></li></ul>2020-01-16 20:57:29,402: INFO: 139820765189888: run(100): main: Main thread finished queueing batches

Searching '/datadisks/disk1/work/B56509B9/w/AB37097F/e' for test results files

@MattGal
Copy link
Member

MattGal commented Jan 17, 2020

some of those files have unusual characters that might need escaping but otherwise this is looking buggy, taking a peek.

@MattGal
Copy link
Member

MattGal commented Jan 17, 2020

@HaoK this is very interesting because I can't find any file events for non-console logs for that whole job, and from the harness log it only ever lists one file uploading (the console log).

From looking at the console log here there are entries like this:

Found log '/datadisks/disk1/work/B56509B9/w/AB37097F/e/../SendMediumData_Success.log'

... which means that if the file is found in /datadisks/disk1/work/B56509B9/w/AB37097F/e/SendMediumData_Success.log, it's NOT in $HELIX_WORKITEM_UPLOAD_ROOT. I believe this is a bug in the Arcade code trying to make this HTML file (which is weird, I thought it was made on the proverbial "other side" of this connection) and will look for that.

As a workaround, if you start copying your logs (or just creating them) in $HELIX_WORKITEM_UPLOAD_ROOT this should work.

@HaoK
Copy link
Member Author

HaoK commented Jan 17, 2020

Yeah so my first attempt did that, and the files didn't show up as links, so i tried copying them lower to where the console log is. I can try copying them to both locations and see if that does the trick.

@MattGal
Copy link
Member

MattGal commented Jan 17, 2020

Yeah so my first attempt did that, and the files didn't show up as links, so i tried copying them lower to where the console log is. I can try copying them to both locations and see if that does the trick.

From my reading of the reporter that's going to result in double links where one is always non-existent, but it's still useful-ish data to try.

@HaoK
Copy link
Member Author

HaoK commented Jan 17, 2020

🎈 So that did the trick, looks like there's a bug somewhere for you guys, but it takes putting the files in both locations for the links to get generated and be clickable. @jkotalik can you take a quick look at the actual files and make sure that's all of them/what you expect. I just cracked open a few and they look legit to me

@jkotalik
Copy link
Contributor

Where should I be looking? I don't see it here:
image

@HaoK
Copy link
Member Author

HaoK commented Jan 17, 2020

@jkotalik They show up imbedded as links next to the console log, so you have to download the logs.html and they are in that file

@jkotalik
Copy link
Contributor

Yay! I see the logs as well.

@HaoK HaoK marked this pull request as ready for review January 17, 2020 19:08
@HaoK HaoK requested a review from a team January 17, 2020 19:09
@HaoK
Copy link
Member Author

HaoK commented Jan 17, 2020

I'll remove the failing assert once this PR is signed off, since without a failing test you can't actually see the logs

@MattGal
Copy link
Member

MattGal commented Jan 17, 2020

🎈 So that did the trick, looks like there's a bug somewhere for you guys, but it takes putting the files in both locations for the links to get generated and be clickable. @jkotalik can you take a quick look at the actual files and make sure that's all of them/what you expect. I just cracked open a few and they look legit to me

Yes, this is expected because in python os.listdir() is not inherently recursive so it doesn't find the file to put in the HTML unless it's in both places. Added some details to dotnet/arcade#4651 to make that clearer.

@HaoK
Copy link
Member Author

HaoK commented Jan 18, 2020

@MattGal uh oh, looks like the xunit-reporter only works for xml files? Not the trx?

From the logs:

Searching '/datadisks/disk1/work/B1900973/w/A8990937/e' for test results files
Found results file /datadisks/disk1/work/B1900973/w/A8990937/e/TestResults/_b001RV8_2020-01-17_23_46_42.trx with format trx
Worker 0: uploaded 35 results
2020-01-17 23:46:47,703: INFO: 140476561798912: run(104): main: Main thread exiting
+ date -u +%FT%TZ
2020-01-17T23:46:47Z
+ /usr/bin/python3 /datadisks/disk1/work/B1900973/p/xunit-reporter.py
2020-01-17T23:46:48. 85Z	ERROR  	xunit-reporter.py	xunit-reporter(80)	main	Unable to report xunit results: no test results xml file found.
+ exit 1

@MattGal
Copy link
Member

MattGal commented Jan 18, 2020

@MattGal uh oh, looks like the xunit-reporter only works for xml files? Not the trx?

From the logs:

Searching '/datadisks/disk1/work/B1900973/w/A8990937/e' for test results files
Found results file /datadisks/disk1/work/B1900973/w/A8990937/e/TestResults/_b001RV8_2020-01-17_23_46_42.trx with format trx
Worker 0: uploaded 35 results
2020-01-17 23:46:47,703: INFO: 140476561798912: run(104): main: Main thread exiting
+ date -u +%FT%TZ
2020-01-17T23:46:47Z
+ /usr/bin/python3 /datadisks/disk1/work/B1900973/p/xunit-reporter.py
2020-01-17T23:46:48. 85Z	ERROR  	xunit-reporter.py	xunit-reporter(80)	main	Unable to report xunit results: no test results xml file found.
+ exit 1

Sorry about that, I filed dotnet/arcade#4655 and we'll discuss it next week.

@HaoK HaoK changed the title [Helix] See what happens when logging tests are turned on [Helix] Better logging (flaky tests, logged tests) Jan 18, 2020
@jkotalik
Copy link
Contributor

@HaoK can we revert the test change and merge this soon? Ideally, we can get it merged within the next few hours.

@HaoK
Copy link
Member Author

HaoK commented Jan 21, 2020

Sure, was waiting for @dotnet/aspnet-build to review first

@@ -103,10 +103,14 @@ fi

FLAKY_FILTER="Flaky:All=true|Flaky:Helix:All=true|Flaky:Helix:Queue:All=true|Flaky:Helix:Queue:$helix_queue_name=true"
echo "Running known-flaky tests."
$DOTNET_ROOT/dotnet vstest $test_binary_path --TestCaseFilter:"$FLAKY_FILTER"
$DOTNET_ROOT/dotnet vstest $test_binary_path --logger:trx --TestCaseFilter:"$FLAKY_FILTER"
Copy link
Contributor

Choose a reason for hiding this comment

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

Where do the TRX files end up? I wonder because only *.log files are copied into the magic $HELIX_WORKITEM_UPLOAD_ROOT directory or its parent.

Copy link
Member Author

Choose a reason for hiding this comment

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

Trx files are automatically uploaded by the helix infrastructure to azdo, this is how they show up in the test rules tabs, so they come for 'free' to us

Copy link
Member Author

Choose a reason for hiding this comment

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

Backing out the trx on flaky run since its causing the jobs to fail

@HaoK
Copy link
Member Author

HaoK commented Jan 21, 2020

Will merge this once PR goes green, I'll need to update the windows version of runtests in a separate PR, I'll add those changes to #17109

@HaoK HaoK merged commit f1dba10 into master Jan 21, 2020
@HaoK HaoK deleted the haok/helix-log branch January 21, 2020 22:03
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area-infrastructure Includes: MSBuild projects/targets, build scripts, CI, Installers and shared framework
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants