search

haf / expecto

A smooth testing lib for F#. APIs made for humans! Strong testing methodologies for everyone!
Apache License 2.0
663 stars 96 forks source link

No separate stack trace in Azure Pipelines results #350

Open cmeeren opened 4 years ago

cmeeren commented 4 years ago

When using xUnit, my failing tests show a dedicated stack trace below the error message in Azure Pipelines, allowing me to click it to go straight to the relevant line in the repo:

image

However, when using Expecto, the stack trace is printed in the output message, but not available in the UI:

image

I am using Unquote for assertion, but the same happens with Expecto's own failtestf.

I am using YoloDev.Expecto.TestSdk 0.8.0 and my tests are invoked on the CI server using

dotnet test path/to/project --logger trx --results-directory d:\a\_temp -c Release --no-build

This command "just works" with xUnit, but apparently not Expecto.

Is there any way to make Expecto stack traces available to Azure Pipelines? Is this something that must be implemented by Expecto, or something I must configure? If the latter, could it perhaps be changed to "just work", like xUnit?

haf commented 4 years ago

My guess is that Microsoft has special-cased xUnit; perhaps if you compare the exact stacktrace output and/or any lines that come just before it, you'll find why and could send a PR that fixes it. WIll you give it a shot?

cmeeren commented 4 years ago

if you compare the exact stacktrace output and/or any lines that come just before it, you'll find why and could send a PR that fixes it.

I'd like to help, but I don't understand what you're suggesting I compare. The stack trace in the screenshot I show above? In some file produced by the test runner? Could you elaborate?

haf commented 4 years ago

They both print to the stdout, and one is recognised, the other one is not. I'd bet one is recognised due to its unique fingerprint; that is, the particular formatting that xUnit has of its output. So if you'd make Expecto print stacktraces identically, perhaps it would start working. Or perhaps Azure is pluggable and there's a specific format we can print in, like for TeamCity?

cmeeren commented 4 years ago

Example xUnit output:

  Stack Trace:
     at ChkBoxApi.SmokeTests.Tests.SmokeTests.testSuccessStatusCode(Response resp) in d:\a\1\s\src\ChkBoxApi.SmokeTests\Tests.fs:line 124
   at ChkBoxApi.SmokeTests.Tests.SmokeTests.Can query cards(SubSystem subSystem) in d:\a\1\s\src\ChkBoxApi.SmokeTests\Tests.fs:line 220

Example Expecto output (different test):

   at ChkBoxApi.SmokeTests.Tests.testSuccessStatusCode@118.Invoke(String x) in d:\a\1\s\src\ChkBoxApi.SmokeTests\Tests.fs:line 118
   at ChkBoxApi.SmokeTests.Tests.testSuccessStatusCode(Response resp) in d:\a\1\s\src\ChkBoxApi.SmokeTests\Tests.fs:line 118
   at ChkBoxApi.SmokeTests.Tests.tests@271-11.Invoke(Unit unitVar0) in d:\a\1\s\src\ChkBoxApi.SmokeTests\Tests.fs:line 277
   at Expecto.Impl.execTestAsync@960-1.Invoke(Unit unitVar)
   at Microsoft.FSharp.Control.AsyncPrimitives.CallThenInvoke[T,TResult](AsyncActivation`1 ctxt, TResult result1, FSharpFunc`2 part2) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 398

If it's in the output message, I expect it's the presence of the initial Stack Trace: line.

cmeeren commented 4 years ago

In case it's relevant, here is info about supported test result formats for Azure Pipelines. In particular, search the table for "Stack" to see what will be picked up for each supported format.

For TRX, it's one of these:

The rest of the page may be worth reading. Making sure Expecto generates output supported by Azure Pipelines will likely make a lot of devs very happy. (Apart from the missing stack trace, I haven't noticed anything else missing, though I haven't looked and have only used Azure Pipelines for a week and Expecto for a few days.)

haf commented 4 years ago

Perhaps it would be worth it for you to write an Azure pipeline printer? We already have a Teamcity one; https://github.com/haf/expecto/blob/2462fb8614d4190206155b193dcde81de3a6dd4a/Expecto/Expecto.fs#L786-L866 that gets automatically used if necessary https://github.com/haf/expecto/blob/2462fb8614d4190206155b193dcde81de3a6dd4a/Expecto/Expecto.fs#L941-L945

cmeeren commented 4 years ago

Adding support to Expecto via a separate printer sounds like a good idea.

According to https://github.com/MicrosoftDocs/vsts-docs/issues/4051 the TF_BUILD variable can be used for detection.

I have no idea how to configure the printer though, both because I don't know what Azure Pipelines expects from the output (again, I haven't noticed anything missing other than the stack trace), and because the Expecto/printer configuration seems to be largely undocumented and I don't understand it. (For example, I tried playing around with it to get inner exceptions before posting #348, but couldn't get anywhere.)

Perhaps an Azure Pipeline printer can be added to Expecto like the TeamCity one, currenly using the defaults but with the added Stack Trace: line?

haf commented 4 years ago

@cmeeren Perhaps you can file a support issue with MSFT and ask them? I don't know either

cmeeren commented 4 years ago

Perhaps it's not the console output, but the rest results file? According to the docs a variety of test result files are supported:

Supported results formats include CTest, JUnit (including PHPUnit), NUnit 2, NUnit 3, Visual Studio Test (TRX), and xUnit 2.

I don't know enough about unit test infrastructure to know how Expecto (or other test frameworks) produce test result files. Does this information tell you anything?

I currently use TRX (the default) when running on Azure Pipelines.

cmeeren commented 4 years ago

Here's a repro solution showing the difference between xUnit and Expecto output:

TestOutput.zip

From the repo root, run dotnet test --logger trx --results-directory test_output.

Note that there's something weird going on with encoded carriage returns (
) in Expecto's stack trace. The line endings in the file are generally CRLF, but in the stack trace they're LF, and the CR are encoded. Could that be the issue? (I'm using Windows, both locally and as Azure Pipelines agents.)

Expecto output:

<?xml version="1.0" encoding="utf-8"?>
<TestRun id="fde72b50-e734-42cb-a6d6-413eca9b0fe9" name="Christer@ZELDA 2019-10-21 10:13:54" runUser="ZELDA\Christer" xmlns="http://microsoft.com/schemas/VisualStudio/TeamTest/2010">
  <Times creation="2019-10-21T10:13:54.6001710+02:00" queuing="2019-10-21T10:13:54.6001742+02:00" start="2019-10-21T10:13:53.5909591+02:00" finish="2019-10-21T10:13:54.6364610+02:00" />
  <TestSettings name="default" id="3231e4bf-c412-42c9-a96a-9fdded681913">
    <Deployment runDeploymentRoot="Christer_ZELDA_2019-10-21_10_13_54" />
  </TestSettings>
  <Results>
    <UnitTestResult executionId="8932c3eb-4347-4c97-a342-11dafd3357a0" testId="59760fed-05ea-c435-b815-e26ca4856b67" testName="fails" computerName="ZELDA" duration="00:00:00.0130000" startTime="2019-10-21T10:13:54.3481435+02:00" endTime="2019-10-21T10:13:54.3990483+02:00" testType="13cdc9d9-ddb5-4fa4-a97d-d965ccfc6d4b" outcome="Failed" testListId="8c84fa94-04c1-424b-9868-57a2d4851a1d" relativeResultsDirectory="8932c3eb-4347-4c97-a342-11dafd3357a0">
      <Output>
        <ErrorInfo>
          <Message>This is an exception</Message>
          <StackTrace>   at Test.test@7.Invoke(Unit unitVar0) in C:\Users\Christer\Desktop\TestOutput\TestOutput\TestOutput.Expecto\Test.fs:line 8&#xD;
   at Expecto.Impl.execTestAsync@960-1.Invoke(Unit unitVar)&#xD;
   at Microsoft.FSharp.Control.AsyncPrimitives.CallThenInvoke[T,TResult](AsyncActivation`1 ctxt, TResult result1, FSharpFunc`2 part2) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 398&#xD;
   at &lt;StartupCode$FSharp-Core&gt;.$Async.StartChild@1650-5.Invoke(AsyncActivation`1 ctxt) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 1650&#xD;
   at Microsoft.FSharp.Control.Trampoline.Execute(FSharpFunc`2 firstAction) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 109</StackTrace>
        </ErrorInfo>
      </Output>
    </UnitTestResult>
  </Results>
  <TestDefinitions>
    <UnitTest name="fails" storage="c:\users\christer\desktop\testoutput\testoutput\testoutput.expecto\bin\debug\netcoreapp3.0\testoutput.expecto.dll" id="59760fed-05ea-c435-b815-e26ca4856b67">
      <Execution id="8932c3eb-4347-4c97-a342-11dafd3357a0" />
      <TestMethod codeBase="C:\Users\Christer\Desktop\TestOutput\TestOutput\TestOutput.Expecto\bin\Debug\netcoreapp3.0\TestOutput.Expecto.dll" adapterTypeName="executor://yolodev/expecto" className="TestOutput.Expecto" name="fails" />
    </UnitTest>
  </TestDefinitions>
  <TestEntries>
    <TestEntry testId="59760fed-05ea-c435-b815-e26ca4856b67" executionId="8932c3eb-4347-4c97-a342-11dafd3357a0" testListId="8c84fa94-04c1-424b-9868-57a2d4851a1d" />
  </TestEntries>
  <TestLists>
    <TestList name="Results Not in a List" id="8c84fa94-04c1-424b-9868-57a2d4851a1d" />
    <TestList name="All Loaded Results" id="19431567-8539-422a-85d7-44ee4e166bda" />
  </TestLists>
  <ResultSummary outcome="Failed">
    <Counters total="1" executed="1" passed="0" failed="1" error="0" timeout="0" aborted="0" inconclusive="0" passedButRunAborted="0" notRunnable="0" notExecuted="0" disconnected="0" warning="0" completed="0" inProgress="0" pending="0" />
  </ResultSummary>
</TestRun>

xUnit output:

<?xml version="1.0" encoding="utf-8"?>
<TestRun id="6a9d9330-b2e7-4b70-91bd-a2382c488cfb" name="Christer@ZELDA 2019-10-21 10:13:56" runUser="ZELDA\Christer" xmlns="http://microsoft.com/schemas/VisualStudio/TeamTest/2010">
  <Times creation="2019-10-21T10:13:56.6876068+02:00" queuing="2019-10-21T10:13:56.6876092+02:00" start="2019-10-21T10:13:55.3226631+02:00" finish="2019-10-21T10:13:56.7135898+02:00" />
  <TestSettings name="default" id="67e156f7-de75-42b5-bc39-2b4d83590553">
    <Deployment runDeploymentRoot="Christer_ZELDA_2019-10-21_10_13_56" />
  </TestSettings>
  <Results>
    <UnitTestResult executionId="b9f66be0-9424-4e9a-9d02-97b22e6ab6f6" testId="90f560c3-ebe5-da3f-b73c-9488f30feb7c" testName="Test.fails" computerName="ZELDA" duration="00:00:00.0029424" startTime="2019-10-21T10:13:56.5247439+02:00" endTime="2019-10-21T10:13:56.5248379+02:00" testType="13cdc9d9-ddb5-4fa4-a97d-d965ccfc6d4b" outcome="Failed" testListId="8c84fa94-04c1-424b-9868-57a2d4851a1d" relativeResultsDirectory="b9f66be0-9424-4e9a-9d02-97b22e6ab6f6">
      <Output>
        <ErrorInfo>
          <Message>System.Exception : This is an exception</Message>
          <StackTrace>   at Test.fails() in C:\Users\Christer\Desktop\TestOutput\TestOutput\TestOutput.xUnit\Test.fs:line 8</StackTrace>
        </ErrorInfo>
      </Output>
    </UnitTestResult>
  </Results>
  <TestDefinitions>
    <UnitTest name="Test.fails" storage="c:\users\christer\desktop\testoutput\testoutput\testoutput.xunit\bin\debug\netcoreapp3.0\testoutput.xunit.dll" id="90f560c3-ebe5-da3f-b73c-9488f30feb7c">
      <Execution id="b9f66be0-9424-4e9a-9d02-97b22e6ab6f6" />
      <TestMethod codeBase="C:\Users\Christer\Desktop\TestOutput\TestOutput\TestOutput.xUnit\bin\Debug\netcoreapp3.0\TestOutput.xUnit.dll" adapterTypeName="executor://xunit/VsTestRunner2/netcoreapp" className="Test" name="Test.fails" />
    </UnitTest>
  </TestDefinitions>
  <TestEntries>
    <TestEntry testId="90f560c3-ebe5-da3f-b73c-9488f30feb7c" executionId="b9f66be0-9424-4e9a-9d02-97b22e6ab6f6" testListId="8c84fa94-04c1-424b-9868-57a2d4851a1d" />
  </TestEntries>
  <TestLists>
    <TestList name="Results Not in a List" id="8c84fa94-04c1-424b-9868-57a2d4851a1d" />
    <TestList name="All Loaded Results" id="19431567-8539-422a-85d7-44ee4e166bda" />
  </TestLists>
  <ResultSummary outcome="Failed">
    <Counters total="1" executed="1" passed="0" failed="1" error="0" timeout="0" aborted="0" inconclusive="0" passedButRunAborted="0" notRunnable="0" notExecuted="0" disconnected="0" warning="0" completed="0" inProgress="0" pending="0" />
    <Output>
      <StdOut>[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.1 (64-bit .NET Core 3.0.0)&#xD;
[xUnit.net 00:00:00.45]   Discovering: TestOutput.xUnit&#xD;
[xUnit.net 00:00:00.52]   Discovered:  TestOutput.xUnit&#xD;
[xUnit.net 00:00:00.52]   Starting:    TestOutput.xUnit&#xD;
[xUnit.net 00:00:00.63]       System.Exception : This is an exception&#xD;
[xUnit.net 00:00:00.63]       Stack Trace:&#xD;
[xUnit.net 00:00:00.63]         C:\Users\Christer\Desktop\TestOutput\TestOutput\TestOutput.xUnit\Test.fs(8,0): at Test.fails()&#xD;
[xUnit.net 00:00:00.64]   Finished:    TestOutput.xUnit&#xD;
</StdOut>
    </Output>
    <RunInfos>
      <RunInfo computerName="ZELDA" outcome="Error" timestamp="2019-10-21T10:13:56.5216623+02:00">
        <Text>[xUnit.net 00:00:00.63]     Test.fails [FAIL]</Text>
      </RunInfo>
    </RunInfos>
  </ResultSummary>
</TestRun>
haf commented 4 years ago

If it's based on the test results file; we support it https://github.com/haf/expecto#testresults-file

cmeeren commented 4 years ago

Not sure how to interpret your comment. On Azure Pipelines, the tests are run using dotnet test --logger trx --results-directory some/dir. This produces the file shown above (Expecto and xUnit for comparison). Azure Pipelines seems to correctly interpret eveything except the stack trace.

Are you saying that with Expecto, I can't expect dotnet test --logger trx to work; that I have to install Expecto.TestResults and then run the tests as a console application instead of using dotnet test, and explicitly call TestResults.write... in code?

Basically, dotnet test --logger trx works fine with Expecto (without Expecto.TestResults), except for the stack trace, which can't be interpreted for some reason. Otherwise dotnet test --logger trx is already working.

haf commented 4 years ago

Hi, I just thought that if a TestResults.xml file was generated, Azure would find it, but I guess you're successfully running Expecto and generating such a file already.

I'm actually not sure; and XML normally has \n linefeeds from my experience, not \r\n linefeeds, but like you say, if you're on Windows, the stacktrace is made up of \r\n linefeeds, but the XML is not; so encoded linefeeds seems right.

I don't see any difference between xunit/expecto XML though? Besides xUnit in this case having only a single line in its stacktrace.

Sorry for not being of more help. Perhaps filing a support issue with Azure is the best way forward?

cmeeren commented 4 years ago

Oh, I've found the source of the confusion now.

When a test fails with an exception, the stack trace works fine.

However, I was using failtestf instead of failwithf. In that case, Expecto prints the stack at the failtestf location (as seen in the second image in the issue description), but does not actually output it as a stack trace.

My question then is, could Expecto output a proper stack trace when using failtest?

haf commented 4 years ago

But isn't our discussion about what a "proper stack trace is"? If you find what makes it proper, then PR that and we'll run with it ;)

That said, inside tests, use "failtestf" not "failwithf"; erroring tests indicate a problematic programming methodology inside your code, when your code fails with exceptions rather than being total over their respective inputs (imo). And outside your code, in your tests, we'd be better off to make the stacktraces that Expect and failtestf print, "proper".

cmeeren commented 4 years ago

What I meant was this:

When using failwith, the output contains a <StackTrace>, as it should:

    <UnitTestResult executionId="991ec957-ff0f-4b3d-bd60-76fbf7c62611" testId="915dd1c4-9340-7bed-6d1c-c27d7fe973e5" testName="tests/this test is using failwith" computerName="ZELDA" duration="00:00:00.0060000" startTime="2019-10-22T14:49:42.6468985+02:00" endTime="2019-10-22T14:49:42.6764041+02:00" testType="13cdc9d9-ddb5-4fa4-a97d-d965ccfc6d4b" outcome="Failed" testListId="8c84fa94-04c1-424b-9868-57a2d4851a1d" relativeResultsDirectory="991ec957-ff0f-4b3d-bd60-76fbf7c62611">
      <Output>
        <ErrorInfo>
          <Message>This is an exception</Message>
          <StackTrace>   at Test.tests@11-1.Invoke(Unit unitVar0) in C:\Users\Christer\Desktop\TestOutput\TestOutput.Expecto\Test.fs:line 12&#xD;
   at Expecto.Impl.execTestAsync@960-1.Invoke(Unit unitVar)&#xD;
   at Microsoft.FSharp.Control.AsyncPrimitives.CallThenInvoke[T,TResult](AsyncActivation`1 ctxt, TResult result1, FSharpFunc`2 part2) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 398&#xD;
   at &lt;StartupCode$FSharp-Core&gt;.$Async.StartChild@1650-5.Invoke(AsyncActivation`1 ctxt) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 1650&#xD;
   at Microsoft.FSharp.Control.Trampoline.Execute(FSharpFunc`2 firstAction) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 109</StackTrace>
        </ErrorInfo>
      </Output>
    </UnitTestResult>

However, when using failtest, the results only contain a <Message> (with the stack trace), not a <StackTrace>:

    <UnitTestResult executionId="9e55dc6c-a590-4143-9b5c-e58970ded5ef" testId="e8919669-a9a7-acb9-8d5b-4cb4a59fd343" testName="tests/this test is using failtest" computerName="ZELDA" duration="00:00:00.0060000" startTime="2019-10-22T14:49:42.6468986+02:00" endTime="2019-10-22T14:49:42.6797726+02:00" testType="13cdc9d9-ddb5-4fa4-a97d-d965ccfc6d4b" outcome="Failed" testListId="8c84fa94-04c1-424b-9868-57a2d4851a1d" relativeResultsDirectory="9e55dc6c-a590-4143-9b5c-e58970ded5ef">
      <Output>
        <ErrorInfo>
          <Message>
This is not an exception
   at Test.tests@8.Invoke(Unit unitVar0) in C:\Users\Christer\Desktop\TestOutput\TestOutput.Expecto\Test.fs:line 9&#xD;
   at Expecto.Impl.execTestAsync@960-1.Invoke(Unit unitVar)&#xD;
   at Microsoft.FSharp.Control.AsyncPrimitives.CallThenInvoke[T,TResult](AsyncActivation`1 ctxt, TResult result1, FSharpFunc`2 part2) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 398&#xD;
   at &lt;StartupCode$FSharp-Core&gt;.$Async.StartChild@1650-5.Invoke(AsyncActivation`1 ctxt) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 1650&#xD;
   at Microsoft.FSharp.Control.Trampoline.Execute(FSharpFunc`2 firstAction) in E:\A\_work\130\s\src\fsharp\FSharp.Core\async.fs:line 109</Message>
        </ErrorInfo>
      </Output>
    </UnitTestResult>

My suggestion is to move the stack trace from <Message> to <StackTrace> when using failtest, just like failwith.

For reference, here is the complete test output file:

output.zip

And here is the code that produced it:

module Test

open Expecto

[<Tests>]
let tests = 
  testList "tests" [
    testCase "this test is using failtest" <| fun () ->
      failtest "This is not an exception"

    testCase "this test is using failwith" <| fun () ->
      failwith "This is an exception"
  ]

[<EntryPoint>]
let main args =
  runTestsInAssembly defaultConfig args

And here is the command:

dotnet test --logger trx --results-directory test_output
haf commented 4 years ago

Good point! However, it requires a bit of remaking of the Expect module, responsible for printing the errors.

haf commented 4 years ago

So, I'm working on a newer API with more "flowy" assertions, similar to how Elm tests does it, to let the test functions return the message values. I don't have time/resources to complete it right now; as I want to get a fully-fledged tracing demo out for Logary right now, but I'm willing to spend a few hours on G showing it to you if you're up for the discussions and then working with me/spending time on this? If nothing else, it would let you get into how to work when developing this library.

cmeeren commented 4 years ago

I appreciate the invitation, but unfortunately I am full up for the foreseeable future. I don't even have the capacity to properly care for the projects I maintain, so I'm afraid I can't take on any more right now.

haf commented 4 years ago

I know what that's like ;). At least with this thread it's clearly documented what needs fixing and it's not even a big fire that stacktraces don't show up, so we can let it be right now until one of us has time to pick it back up.