Rotating file logs V3

[iowillhoit]

Outcome of this SPIKE

@W-10745422@

forcedotcom/cli#1408

Implements the rotating log stream supported in Bunyan into sfdx-core's logger

Testing instructions

• Pull this branch of sfdx-core
• Run yarn build
• Run yarn link
• cd to local cli (sf)
• Pull this branch of sf Rotating log file salesforcecli/cli#199
• Run yarn
• Run npm ls @salesforce/core
  • Confirm all 3.x versions of core are the same
• Run yarn link @salesforce/core
• Run a command that will log
  • Example: SF_LOG_ROTATION_PERIOD='5000ms' SFDX_LOG_LEVEL=trace bin/dev env list
    • Note bin/dev
• Run command a few more times
• Notice that you now have multiple log files in your ~/.sf directory (sf.log, sf.log.0, sf.log.1, sf.log.2)
• Notice how logs move to "next" log file as commands are ran.
  • Watch files with tail -F sf.log

Worth noting

• There is a potential for orphaned log files (conversation)
• Existing huge log files will be automatically cleaned up with this change. The only downside is that when an existing large log files gets removed (on the 3rd day with current defaults), it will potentially take a very long time to remove the file and the user will have no indication as to what is happening.
  • This can be tested by creating a large file in place of sf.log and run commands until is is removed.
    • Create large file on mac: mkfile 30g ./sf.log
    • Then time how long commands take until it is removed. In my testing time bin/run force:org:list typically took about 5 seconds to run but when my 30gb was cleared it took close to 15 seconds.
• The ms interval does not behave exactly like the other intervals. Hourly, Daily, Weekly, etc will "switch" log files at the start of a new period (e.g. daily happens at midnight). Docs on "period" here. Milliseconds will rotate logs on each command regardless. This can be tested a little more accurately by modifying Bunyan's code slightly.
  • In your linked core directory (cli/node_modules/@salesforce/core/node_modules/@salesforce/bunyan/lib/bunyan.js) change:

  var m = /^([1-9][0-9]*)([hdwmy]|ms)$/.exec(period);
  // to
  var m = /^([1-9][0-9]*)([hdwmy]|ms|min)$/.exec(period);

  • And then add the following to the switch statement on line 1314:

  case 'min':
      if (this.rotAt) {
          rotAt = this.rotAt + this.periodNum * 60 * 60 * 60 * 1000 * periodOffset;
      } else {
          // First time: top of the next minute.
          rotAt = Date.UTC(d.getUTCFullYear(), d.getUTCMonth(),
              d.getUTCDate(), d.getUTCHours(), d.getUTCMinutes() + periodOffset);
      }
      break;

  • You can now use min intervals and the logs will rotate at the start of each new minute
    • SF_LOG_ROTATION_PERIOD='1min' SFDX_LOG_LEVEL=trace bin/dev env list