Unable to get Junit test result format when running Apex tests

[alan-morey]

Summary

Error "Invalid time value" occurs when executing force:apex:test:run or force:apex:test:report with the result format specified as -r junit

Steps To Reproduce:

MyTest.cls

@IsTest(isParallel = true)
class MyTest {
    @IsTest
    static void shouldFail() {
        System.assertEquals(1, 1 + 1);
    }

    @IsTest
    static void shouldPass() {
        System.assertEquals(2, 1 + 1);
    }
}

Run apex test and specify result format as junit:

sfdx force:apex:test:run --wait -1 -r junit -t MyTest

Expected result

Expected test results written to standard output in Junit format

Actual result

Results are output as JSON and error occurs

$ sfdx force:apex:test:run --wait -1 -r junit -t MyTest
{
  "summary": {
    "outcome": "Failed",
    "testsRan": 2,
    "passing": 1,
    "failing": 1,
    "skipped": 0,
    "passRate": "50%",
    "failRate": "50%",
    "skipRate": "0%",
    "testStartTime": "Thu Jun 24 2021 12:30:14 p.m.",
    "testExecutionTimeInMs": 34,
    "testTotalTimeInMs": 34,
    "commandTimeInMs": 287,
    "hostname": "https://example--alandev01.my.salesforce.com",
    "orgId": "00D1F000000YO2SUAW",
    "username": "[email protected]",
    "testRunId": "7071F0000208syH",
    "userId": "00530000003ZbzsAAC"
  },
  "tests": [
    {
      "id": "07M1F00000Mb95RUAR",
      "queueItemId": "7091F000002PGCzQAO",
      "stackTrace": "Class.Assert.fail: line 95, column 1\nClass.Assert.failNotEquals: line 145, column 1\nClass.Assert.equals: line 127, column 1\nClass.Assert.equals: line 108, column 1\nClass.MyTest.shouldFail: line 5, column 1",
      "message": "System.AssertException: Assertion Failed: Expected: <1>, Actual: <2>",
      "asyncApexJobId": "7071F0000208syHQAQ",
      "methodName": "shouldFail",
      "outcome": "Fail",
      "apexLogId": null,
      "apexClass": {
        "id": "01p1F00000JCxPPQA1",
        "name": "MyTest",
        "namespacePrefix": null,
        "fullName": "MyTest"
      },
      "runTime": 14,
      "testTimestamp": "2021-06-24T19:30:15.000+0000",
      "fullName": "MyTest.shouldFail",
      "diagnostic": {
        "exceptionMessage": "System.AssertException: Assertion Failed: Expected: <1>, Actual: <2>",
        "exceptionStackTrace": "Class.Assert.fail: line 95, column 1\nClass.Assert.failNotEquals: line 145, column 1\nClass.Assert.equals: line 127, column 1\nClass.Assert.equals: line 108, column 1\nClass.MyTest.shouldFail: line 5, column 1",
        "className": "Assert",
        "compileProblem": "",
        "lineNumber": 95,
        "columnNumber": 1
      }
    },
    {
      "id": "07M1F00000Mb95SUAR",
      "queueItemId": "7091F000002PGCzQAO",
      "stackTrace": null,
      "message": null,
      "asyncApexJobId": "7071F0000208syHQAQ",
      "methodName": "shouldPass",
      "outcome": "Pass",
      "apexLogId": null,
      "apexClass": {
        "id": "01p1F00000JCxPPQA1",
        "name": "MyTest",
        "namespacePrefix": null,
        "fullName": "MyTest"
      },
      "runTime": 20,
      "testTimestamp": "2021-06-24T19:30:38.000+0000",
      "fullName": "MyTest.shouldPass"
    }
  ]
}
Encountered an error when processing test results
RangeError: Invalid time value
    at Date.toISOString (<anonymous>)
    at JUnitReporter.format (/home/alan/.local/share/sfdx/client/7.107.0-621a7d2/node_modules/@salesforce/apex-node/lib/src/reporters/junitReporter.js:19:65)
    at Run.logJUnit (/home/alan/.local/share/sfdx/client/7.107.0-621a7d2/node_modules/@salesforce/plugin-apex/lib/commands/force/apex/test/run.js:164:30)
    at Run.<anonymous> (/home/alan/.local/share/sfdx/client/7.107.0-621a7d2/node_modules/@salesforce/plugin-apex/lib/commands/force/apex/test/run.js:83:30)
    at Generator.next (<anonymous>)
    at fulfilled (/home/alan/.local/share/sfdx/client/7.107.0-621a7d2/node_modules/@salesforce/plugin-apex/node_modules/tslib/tslib.js:112:62)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)

Additional information

Same result occurs when using force:apex:test:report

sfdx force:apex:test:report --wait -1 -r junit -i 7071F0000208syH

If the output directory flag is also specified, the output is slightly different but the result is still an error.

$ sfdx force:apex:test:run -r junit -w -1 -t MyTest -d test-results
WARNING: WARNING: In the Summer ’21 release, we'll rename or remove some of the output files that are created when you run force:apex:test:run or force:apex:test:report with the --outputdir (-d) parameter.  This breaking change could impact your CI/CD scripts if they reference specific filenames. See https://sfdc.co/apex-test-updates for details

ERROR running force:apex:test:run:  Invalid time value

No output files are written and the output directory test-results does not gets created.

SFDX CLI Version(to find the version of the CLI engine run sfdx --version): sfdx-cli/7.107.0 linux-x64 node-v14.17.1

SFDX plugin Version(to find the version of the CLI plugin run sfdx plugins --core)

 sfdx plugins --core
@alan-morey/sfdx-plugin 0.0.0 (link) /home/alan/repos/alan-morey-sfdx-plugin                                                                                                   
@oclif/plugin-autocomplete 0.3.0                                                                                                                                               
@oclif/plugin-commands 1.3.0 (core)
@oclif/plugin-help 3.2.2 (core)
@oclif/plugin-not-found 1.2.4 (core)
@oclif/plugin-plugins 1.10.0 (core)
@oclif/plugin-update 1.4.0-3 (core)
@oclif/plugin-warn-if-update-available 1.7.0 (core)
@oclif/plugin-which 1.0.3 (core)
@salesforce/sfdx-diff 0.0.6
@salesforce/sfdx-plugin-lwc-test 0.1.7 (core)
@salesforce/sfdx-scanner 2.9.2
@salesforce/sfdx-trust 3.6.0 (core)
alias 1.1.10 (core)
apex 0.2.2 (core)
apexlink 1.3.2
auth 1.6.1 (core)
config 1.2.8 (core)
custom-metadata 1.0.12 (core)
data 0.4.12 (core)
generator 1.1.7 (core)
gr-sfdx-plugin 0.0.0 (link) /home/alan/repos/salesforce/gr-sfdx-plugin
limits 1.2.1 (core)
org 1.6.7 (core)
salesforce-alm 52.0.2 (core)
schema 1.0.7 (core)
sfdx-cli 7.107.0 (core)
telemetry 1.2.2 (core)
templates 52.0.0 (core)                                                                                                                                                        
user 1.3.0 (core)   

OS and version: Ubuntu 18.04.5 LTS

[github-actions]

Thank you for filing this issue. We appreciate your feedback and will review the issue as soon as possible. Remember, however, that GitHub isn't a mechanism for receiving support under any agreement or SLA. If you require immediate assistance, contact Salesforce Customer Support.

[shetzel]

fyi: @AnanyaJha

[AnanyaJha]

Hi @alan-morey thanks for reporting this! Unfortunately, we weren't able to repro this locally. Can you provide us with a sample repository to test out this scenario?

[alan-morey]

@AnanyaJha Did you try to reproduce on Linux?

FYI, it does not seem to be a bug on Windows, my team are on Windows machines and -r junit works as expected for them.

[randi274]

@alan-morey are you still facing this issue with a current CLI? I tried to reproduce this issue just now on my mac with the CLI version 7.126.0, and the junit looks good for me (test code snippet failing as expected).

[alan-morey]

@randi274 Yes, still facing this issue. Yesterday I upgraded to latest and still problem persists

 CLI Version : 
        sfdx-cli/7.127.0

 Architecture: 
        linux-x64

 Node Version : 
        node-v14.18.1

 Plugin Version: 
        @oclif/plugin-autocomplete 0.3.0 (core)
        @oclif/plugin-commands 1.3.0 (core)
        @oclif/plugin-help 3.2.5 (core)
        @oclif/plugin-not-found 1.2.4 (core)
        @oclif/plugin-plugins 1.10.2 (core)                                                                                                                                               
        @oclif/plugin-update 1.5.0 (core)                                                                                                                                                 
        @oclif/plugin-warn-if-update-available 1.7.0 (core)
        @oclif/plugin-which 1.0.3 (core)
        @salesforce/sfdx-plugin-lwc-test 0.1.7 (core)
        alias 1.1.22 (core)
        apex 0.3.0 (core)
        auth 1.7.5 (core)
        config 1.2.47 (core)
        custom-metadata 1.0.12 (core)
        data 0.6.4 (core)
        generator 1.2.1 (core)
        gr-sfdx-plugin 0.0.0 (link) /home/alan.morey/repos/salesforce/gr-sfdx-plugin
        limits 1.2.3 (core)
        org 1.9.0 (core)
        salesforce-alm 53.4.2 (core)
        schema 1.0.10 (core)
        sfdx-cli 7.127.0 (core)
        source 1.4.0 (core)
        telemetry 1.2.8 (core)
        templates 52.6.0 (core)
        trust 1.0.11 (core)
        user 1.5.2 (core)

 OS and Version: 
        Linux 5.4.0-89-generic

Taking a deeper look into this, I have an actual JSON response example as follows:

{
  "summary": {
    "outcome": "Passed",
    "testsRan": 2,
    "passing": 2,
    "failing": 0,
    "skipped": 0,
    "passRate": "100%",
    "failRate": "0%",
    "skipRate": "0%",
    "testStartTime": "Tue Nov 23 2021 9:19:29 a.m.",
    "testExecutionTimeInMs": 70,
    "testTotalTimeInMs": 70,
    "commandTimeInMs": 3146,
    "hostname": "https://example--devint.my.salesforce.com",
    "orgId": "00D7j000000H2CDEA0",
    "username": "[email protected]",
    "testRunId": "7077j00001fzuLf",
    "userId": "00530000003aGEGAA2"
  },
  "tests": [
    {
      "id": "07M7j000006OhAfEAK",
      "queueItemId": "7097j000000lAOcAAM",
      "stackTrace": null,
      "message": null,
      "asyncApexJobId": "7077j00001fzuLfAAI",
      "methodName": "of_shouldGenerateKeyForComponentsTreatingNullAsEmptyString_whenGivenNullComponents",
      "outcome": "Pass",
      "apexLogId": null,
      "apexClass": {
        "id": "01p14000001G6QZAA0",
        "name": "CompositeKeyTest",
        "namespacePrefix": null,
        "fullName": "CompositeKeyTest"
      },
      "runTime": 21,
      "testTimestamp": "2021-11-23T17:19:30.000+0000",
      "fullName": "CompositeKeyTest.of_shouldGenerateKeyForComponentsTreatingNullAsEmptyString_whenGivenNullComponents"
    },
    {
      "id": "07M7j000006OhAgEAK",
      "queueItemId": "7097j000000lAOcAAM",
      "stackTrace": null,
      "message": null,
      "asyncApexJobId": "7077j00001fzuLfAAI",
      "methodName": "of_shouldGenerateKeyForComponents_whenGivenArguments",
      "outcome": "Pass",
      "apexLogId": null,
      "apexClass": {
        "id": "01p14000001G6QZAA0",
        "name": "CompositeKeyTest",
        "namespacePrefix": null,
        "fullName": "CompositeKeyTest"
      },
      "runTime": 49,
      "testTimestamp": "2021-11-23T17:19:51.000+0000",
      "fullName": "CompositeKeyTest.of_shouldGenerateKeyForComponents_whenGivenArguments"
    }
  ]
}

I see summary.testStartTime seems to have different date/time format "Tue Nov 23 2021 9:19:29 a.m." when compared to a test result, tests[0].testTimestamp has "2021-11-23T17:19:30.000+0000".

Based on the error I am receiving:

Encountered an error when processing test results
RangeError: Invalid time value
    at Date.toISOString (<anonymous>)
    at JUnitReporter.format (/home/alan.morey/.npm-packages/lib/node_modules/sfdx-cli/node_modules/@salesforce/apex-node/src/reporters/junitReporter.ts:32:61)
    at Run.logJUnit (/home/alan.morey/.npm-packages/lib/node_modules/sfdx-cli/node_modules/@salesforce/plugin-apex/src/commands/force/apex/test/run.ts:348:26)
    at Run.<anonymous> (/home/alan.morey/.npm-packages/lib/node_modules/sfdx-cli/node_modules/@salesforce/plugin-apex/src/commands/force/apex/test/run.ts:240:16)
    at Generator.next (<anonymous>)
    at fulfilled (/home/alan.morey/.npm-packages/lib/node_modules/sfdx-cli/node_modules/@salesforce/plugin-apex/node_modules/tslib/tslib.js:112:62)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)

Having a look at the junitReport.ts:32 source:

output += `timestamp="${new Date(summary.testStartTime).toISOString()}" `;

We can see that summary.testStartTime is passed to Date constructor but since the date is not valid for parsing, when .toISOString() is called on that date instance the error is raised.

Maybe when the JSON response is being built, it's not correctly formatting the summary.testStartTime same as the testTimestamp?

[randi274]

Thanks for the callout on the time value you were using @alan-morey, that does seem to be the root cause here! I stubbed out the value Tue Nov 23 2021 9:19:29 a.m. in a local environment, and was able to generate the error. It seems like the Date class is not happy with converting that format. On a mac, the same date would read as Tue Nov 23 2021 9:19:29 PM, and if I convert a.m. -> PM it works fine. That should be enough info to log it as a bug and into the backlog. We'll update here once we've got a fix on hand for it!

[uip-robot-zz]

This issue has been linked to a new work item: W-10226817

[mohanraj-r]

Thanks for the info @alan-morey, @randi274

The issue seems to be with

salesforcedx-apex/packages/apex-node/src/utils/dateUtil.ts

Line 21 in 22c9014

return `${date.toDateString()} ${date.toLocaleTimeString()}`;

• I was able to trigger the error by configuring the locale time string to return with a.m., p.m. - e.g. using Ireland english locale with a 12 hour clock seems to do it
  date.toLocaleTimeString('en-ie', { hourCycle: 'h12'})

• The reason behind the error occurring in linux only might be because the linux machine has a different locale and time setting.

• Strangely this issue doesn't occur with node12 for some reason - just FYI

$ docker run -it --rm node:12
Welcome to Node.js v12.22.7.
Type ".help" for more information.
>  date = new Date()
2021-12-18T04:29:19.372Z
> testStartTime=`${date.toDateString()} ${date.toLocaleTimeString('en-ie', { hourCycle: 'h12'})}`
'Sat Dec 18 2021 4:29:19 AM'
> new Date(testStartTime).toISOString()
'2021-12-18T04:29:19.000Z'

• But the Invalid time value error occurs with node14

$ docker run -it --rm node:14
Welcome to Node.js v14.18.2.
Type ".help" for more information.
> date = new Date()
2021-12-18T04:30:53.902Z
> testStartTime=`${date.toDateString()} ${date.toLocaleTimeString('en-ie', { hourCycle: 'h12'})}`
'Sat Dec 18 2021 4:30:53 a.m.'
> new Date(testStartTime).toISOString()
Uncaught RangeError: Invalid time value
    at Date.toISOString (<anonymous>)

• A potential solution would be to force the locale to en-US. This should still respect the timezone and only affect the format. @alan-morey Can you please check if the following code works as expected in the linux machine where the error occurs? I will also try to get hold of a linux vm/container, set locale and test it out.

> date = new Date()
2021-12-18T04:30:53.902Z
> testStartTime=`${date.toDateString()} ${date.toLocaleTimeString('en-US')}`
'Sat Dec 18 2021 4:30:53 AM'
> new Date(testStartTime).toISOString()
'2021-12-18T04:30:53.000Z'

• Another option would be to use UTC time string, but they are not as readable - so would prefer the above solution

> testStartTime=`${date.toDateString()} ${date.toTimeString()}`
'Sat Dec 18 2021 04:30:53 GMT+0000 (Coordinated Universal Time)'
> new Date(testStartTime).toISOString()
'2021-12-18T04:30:53.000Z'

[mohanraj-r]

@alan-morey Can you please post the output of the locale command from the linux machine with the issue so that I can set the same locale and try to replicate the issue.

[alan-morey]

@mohanraj-r

My machine locale is as follows:

$ locale
LANG=en_CA.UTF-8                                                                                                                                                                          
LANGUAGE=en_CA:en
LC_CTYPE="en_CA.UTF-8"
LC_NUMERIC="en_CA.UTF-8"
LC_TIME="en_CA.UTF-8"
LC_COLLATE="en_CA.UTF-8"
LC_MONETARY="en_CA.UTF-8"
LC_MESSAGES="en_CA.UTF-8"
LC_PAPER="en_CA.UTF-8"
LC_NAME="en_CA.UTF-8"
LC_ADDRESS="en_CA.UTF-8"
LC_TELEPHONE="en_CA.UTF-8"
LC_MEASUREMENT="en_CA.UTF-8"
LC_IDENTIFICATION="en_CA.UTF-8"
LC_ALL=

[alan-morey]

@mohanraj-r When the output is to JSON, I think the testStartTime should be formatted as an ISO datetime string, probably using UTC too. To remain consistent with other fields that are datetime strings in the test result. This way all datetimes in a JSON output are given in a predictable format, making it easier for consuming and deserializing back to to some kind of Date or DateTime objects in target programming languages.

However, if the output is just plain text to standard output, then using the user's locale does make sense for more human friendly reading.

[mohanraj-r]

Agree @alan-morey was thinking the same
locale formatted doesn't seem to belong in JSON / Junit format. It probably belongs in human format reporter. ISO would make sense for JSON output.

I am finally able to reproduce the error by setting the locale in env (even in osx)

# Works without error with default locale (en_US)
$ node -e 'console.log(new Date(new Date().toLocaleString()))'
2021-12-21T03:46:54.000Z
# Errors when locale is set to `en_CA`
$ LC_ALL=en_CA node -e 'console.log(new Date(new Date().toLocaleString()))'
Invalid Date

I will do some more final verification and start on a fix.

[HyruleConsulting]

Hi there,
Was this ever resolved? I am finding the same issue in CICD (Linux machine).

Command:
sfdx force:apex:test:run -t -r junit -d

Output:
ERROR running force:apex:test:run: Invalid time value

Seems to be working fine on my Mac, just on CICD it's not working for the last week (Linux based machines)

[HyruleConsulting]

Fixed the issue, I started using a docker container recently and noticed the previous comments about Language and Locale not being set. Setting these environment variables in the image fixed the issue for me too!

For those on linux based CICD or using containers with SFDX CLI. Ensure locale is being set using something like this:

RUN apt-get install -y locales && \
    sed -i '/en_GB.UTF-8/s/^# //g' /etc/locale.gen && \
    locale-gen
    
ENV LANG="en_GB.UTF-8"
ENV LC_COLLATE="en_GB.UTF-8"
ENV LC_CTYPE="en_GB.UTF-8"
ENV LC_MESSAGES="en_GB.UTF-8"
ENV LC_MONETARY="en_GB.UTF-8"
ENV LC_NUMERIC="en_GB.UTF-8"
ENV LC_TIME="en_GB.UTF-8"

[nvuillam]

Any idea about how to fix that with an alpine linux image ?

[nvuillam]

For those who are still stuck, I made a workaround in sfdx-hardis latest docker image

It contains sfdx-cli & other plugins

If you have your own dockerfile, feel free to copy my ugly hack at the end of the Dockerfile -> https://github.com/hardisgroupcom/sfdx-hardis/blob/main/Dockerfile

[shetzel]

Closing this since it should be fixed with #334
Please re-open if you're still seeing the issue after updating to v2.1.2