Skip to content

Add timestamps to XUnitLogChecker output - #86737

Merged
ivdiazsa merged 4 commits into
dotnet:mainfrom
markples:timestamp-logchecker
Jun 7, 2023
Merged

Add timestamps to XUnitLogChecker output#86737
ivdiazsa merged 4 commits into
dotnet:mainfrom
markples:timestamp-logchecker

Conversation

@markples

@markplesmarkples commented May 24, 2023

Copy link
Copy Markdown
Contributor

The main motivation here is to give a quick notification whether a timeout was due to taking a long time or coincidentally hitting some external limit at that point. I think the below is due to the watchdog 119 hitting, and since 9:31:47 isn't long after 9:31:44, then the thread07 test is probably stuck, but I'm never sure that I'm reading it correctly.

/root/helix/work/correlation/watchdog 119 /root/helix/work/correlation/corerun -p System.Reflection.Metadata.MetadataUpdater.IsSupported=false -p System.Runtime.Serialization.EnableUnsafeBinaryFormatterSerialization=true threading_group2.dll ''
09:31:44.737 Running test: baseservices/threading/generics/Monitor/EnterExit01/EnterExit01.dll
Test Passed
09:31:44.875 Passed test: baseservices/threading/generics/Monitor/EnterExit01/EnterExit01.dll
...
09:31:47.302 Running test: baseservices/threading/generics/TimerCallback/thread07_TimerCallback/thread07_TimerCallback.dll
Test Passed
09:31:47.510 Passed test: baseservices/threading/generics/TimerCallback/thread07_TimerCallback/thread07_TimerCallback.dll
09:31:47.512 Running test: baseservices/threading/generics/WaitCallback/thread07_WaitCallback/thread07_WaitCallback.dll
Child process took too long. Timed out... Exiting...
App Exit Code: 110
Expected: 100
Actual: 110
END EXECUTION - FAILED
+ test_exit_code=1
+ dotnet /root/helix/work/correlation/XUnitLogChecker/XUnitLogChecker.dll baseservices/threading/threading_group2 threading_group2 /home/helixbot/dotnetbuild/dumps
[XUnitLogChecker]: Item 'threading_group2' did not finish running. Checking and fixing the log...
[XUnitLogChecker]: XUnit log file has been fixed!
28/95 tests run.
* 28 tests passed.
* 0 tests failed.
* 0 tests skipped.
[XUnitLogChecker]: Checking for dumps...

Here's a snippet from a successful test run for this PR. If the "passed test" line was missing, we would still easily be able to bound the test time under 3 seconds.

18:44:42.835 Running test: JIT/jit64/hfa/main/testC/hfa_nd1C_r/hfa_nd1C_r.cmd
<snip>
18:44:45.041 Passed test: JIT/jit64/hfa/main/testC/hfa_nd1C_r/hfa_nd1C_r.cmd
App Exit Code: 100
Expected: 100
Actual: 100
END EXECUTION - PASSED
PASSED
[XUnitLogChecker]: 18:44:45.25: Item 'jit64_1' did complete successfully!

@ghostghost assigned markplesMay 24, 2023
@ghostghost added the area-Infrastructure-coreclr Only use for closed issues label May 24, 2023
@ghost

Copy link
Copy Markdown

Tagging subscribers to this area: @hoyosjs
See info in area-owners.md if you want to be subscribed.

Issue Details

null

Author:markples
Assignees:markples
Labels:

area-Infrastructure-coreclr

Milestone:-

@markples

markples commented May 26, 2023

Copy link
Copy Markdown
ContributorAuthor

Failures are marked known plus #85993

(new run- no failures)

@markples
markples marked this pull request as ready for review June 2, 2023 23:21
@markples

Copy link
Copy Markdown
ContributorAuthor

@ivdiazsa Does adding these timestamps seem reasonable to you?


static void WriteLineTimestamp(string message)
{
Console.Write($"[XUnitLogChecker]: {System.DateTime.Now:HH:mm:ss.ff}: ");

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Is any concurrent console output possible? I assume not but if it is you might want to make this a single write to the console not two.

@ivdiazsa

Copy link
Copy Markdown
Contributor

/azp run runtime-coreclr outerloop

@azure-pipelines

Copy link
Copy Markdown
Azure Pipelines successfully started running 1 pipeline(s).

@ivdiazsaivdiazsa left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

I think adding the timestamps will definitely prove to be a helpful change. Thanks for doing this work, Mark! And thanks for keeping the format to avoid super long lines of code. LGTM!

I just kicked off an outerloop CI run to be safe. I've had experiences of those breaking in the most unexpected ways 😅. If all's good there, then feel free to merge this unless someone has a reason not to do it yet.

@ivdiazsa

Copy link
Copy Markdown
Contributor

Failures are unrelated to this change, so merging now.

@ivdiazsa
ivdiazsa merged commit a2656af into dotnet:mainJun 7, 2023
@markples

Copy link
Copy Markdown
ContributorAuthor

Thank you for reviewing, launching the test, and merging!

@ghostghost locked as resolved and limited conversation to collaborators Jul 8, 2023
Sign up for freeto subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

area-Infrastructure-coreclrOnly use for closed issues

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants

@markples@ivdiazsa@danmoseley