SFDX logrotation errors at 12am with long-running commands

[jverelst]

Summary

Follow-up from https://github.com/forcedotcom/cli/issues/1408, if you have a long-running SFDX command that passes the 12am mark, the command will start giving errors because probably the current log is being rotated.

Steps To Reproduce:

Run a large testsuite, starting at 23:59

sfdx force:apex:test:run -w 300 -l runlocaltests

Expected result

No errors

Actual result

2022-09-08T00:00:00.0139261Z [Error: ENOENT: no such file or directory, rename '/home/vsts_azpcontainer/.sf/sf.log' -> '/home/vsts_azpcontainer/.sf/sf.log.0'] {
2022-09-08T00:00:00.0140067Z   errno: -2,
2022-09-08T00:00:00.0140490Z   code: 'ENOENT',
2022-09-08T00:00:00.0140901Z   syscall: 'rename',
2022-09-08T00:00:00.0141374Z   path: '/home/vsts_azpcontainer/.sf/sf.log',
2022-09-08T00:00:00.0141889Z   dest: '/home/vsts_azpcontainer/.sf/sf.log.0'
2022-09-08T00:00:00.0142275Z }
2022-09-08T00:00:00.0161881Z [Error: ENOENT: no such file or directory, rename '/home/vsts_azpcontainer/.sf/sf.log' -> '/home/vsts_azpcontainer/.sf/sf.log.0'] {
2022-09-08T00:00:00.0162705Z   errno: -2,
2022-09-08T00:00:00.0163105Z   code: 'ENOENT',
2022-09-08T00:00:00.0163518Z   syscall: 'rename',
2022-09-08T00:00:00.0163983Z   path: '/home/vsts_azpcontainer/.sf/sf.log',
2022-09-08T00:00:00.0164514Z   dest: '/home/vsts_azpcontainer/.sf/sf.log.0'
2022-09-08T00:00:00.0164889Z }
2022-09-08T00:00:00.0179293Z ERROR running force:apex:test:run:  Unknown error in Apex Library: ENOENT: no such file or directory, rename '/home/vsts_azpcontainer/.sf/sf.log' -> '/home/vsts_azpcontainer/.sf/sf.log.0'

System Information

Running SFDX in an Azure pipeline, on an image based on the heroku18 docker container.

{
  "cliVersion": "sfdx-cli/7.166.1",
  "architecture": "linux-x64",
  "nodeVersion": "node-v16.13.1",
  "pluginVersions": [
    "@jayree/sfdx-plugin-legacy 1.0.2 (user)",
    "@jayree/sfdx-plugin-manifest 2.2.10 (user)",
    "@jayree/sfdx-plugin-prettier 1.1.7 (user)",
    "@oclif/plugin-autocomplete 1.3.0 (core)",
    "@oclif/plugin-commands 2.2.0 (core)",
    "@oclif/plugin-help 2.2.3 (user)",
    "@oclif/plugin-not-found 2.3.1 (core)",
    "@oclif/plugin-plugins 2.1.0 (core)",
    "@oclif/plugin-update 3.0.0 (core)",
    "@oclif/plugin-version 1.1.2 (core)",
    "@oclif/plugin-warn-if-update-available 2.0.4 (core)",
    "@oclif/plugin-which 2.1.0 (core)",
    "alias 2.1.0 (core)",
    "apex 1.2.0 (core)",
    "auth 2.2.3 (core)",
    "community 2.0.1 (core)",
    "config 1.4.17 (core)",
    "custom-metadata 2.0.0 (core)",
    "data 2.1.2 (core)",
    "generator 2.0.2 (core)",
    "info 2.0.1 (core)",
    "limits 2.0.1 (core)",
    "org 2.2.0 (core)",
    "packaging 1.5.1 (core)",
    "schema 2.1.1 (core)",
    "signups 1.2.0 (core)",
    "source 2.0.13 (core)",
    "telemetry 2.0.0 (core)",
    "templates 55.1.0 (core)",
    "trust 2.0.3 (core)",
    "user 2.1.0 (core)",
    "@salesforce/sfdx-plugin-lwc-test 1.0.0 (core)",
    "dxb 1.7.12 (user)",
    "salesforce-alm 54.8.1 (core)",
    "sfdmu 4.15.1 (user)",
    "sfdx-browserforce-plugin 2.9.1 (user)",
    "sfdx-jayree 4.3.18 (user)",
    "sfpowerkit 5.0.0 (user)",
    "texei-sfdx-plugin 1.16.5 (user)"
  ],
  "osVersion": "Linux 5.10.76-linuxkit",
  "shell": "bash",
  "rootPath": "/usr/local/lib/nodejs/lib/node_modules/sfdx-cli"
}

Additional information

You can see exactly at 00:00:00 errors are being generated, which result in the entire pipeline failing. This change in log-rotation seems to be the cause.

The pipeline in question usually runs about 5 hours, starting at 8pm GMT, finishing around 1am GMT. But since I upgrade the docker image to have the latest version of SFDX, now the pipeline immediately fails at 00:00.

[github-actions[bot]]

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.

[jverelst]

I just found a workaround that works for me in our pipelines: setting the logrotation period to be longer than 1 day:

SFDX_LOG_ROTATION_PERIOD=1w

[git2gus[bot]]

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