WIP: Tracing

package.json

@@ -1,7 +1,7 @@
 {
-  "name": "yarn",
+  "name": "@stemn/yarn",
   "installationMethod": "unknown",
-  "version": "1.14.0-0",
+  "version": "1.14.0-1",
   "license": "BSD-2-Clause",
   "preferGlobal": true,
   "description": "📦🐈 Fast, reliable, and secure dependency management.",

src/cli/index.js

@@ -25,6 +25,9 @@ import {version} from '../util/yarn-version.js';
 import handleSignals from '../util/signal-handler.js';
 import {boolify, boolifyWithDefault} from '../util/conversion.js';
 
+// STEMN import
+import {benchmark, debug} from './logging.js';
+
 function findProjectRoot(base: string): string {
   let prev = null;
   let dir = base;
@@ -41,6 +44,7 @@ function findProjectRoot(base: string): string {
   return base;
 }
 
+/* [STEMN]: main function here (multiple threads executed) */
 export async function main({
   startArgs,
   args,
@@ -246,6 +250,8 @@ export async function main({
   const outputWrapperEnabled = boolifyWithDefault(process.env.YARN_WRAP_OUTPUT, true);
   const shouldWrapOutput = outputWrapperEnabled && !commander.json && command.hasWrapper(commander, commander.args);
 
+
+
   if (shouldWrapOutput) {
     reporter.header(commandName, {name: 'yarn', version});
   }
@@ -283,6 +289,10 @@ export async function main({
       if (shouldWrapOutput) {
         reporter.footer(false);
       }
+
+      /* [STEMN]: Possible hook here for exitCode conditional code */
+
+
       return exitCode;
     });
   };
@@ -478,6 +488,9 @@ export async function main({
     if (errorReportLoc) {
       reporter.info(reporter.lang('bugReport', errorReportLoc));
     }
+
+    /* [STEMN]: Warn in logs about unexpected error -> inconsistencies */
+    debug(">>>>>>>> WARNING: LOGS MAY BE INCONSISTENT DUE TO ERROR <<<<<<<<\n");
   }
 
   function writeErrorReport(log): ?string {

src/cli/logging.js

@@ -0,0 +1,70 @@
+const fs = require('fs');
+const rl = require("readline");
+const spawn = require('child_process').spawnSync;
+
+
+
+// outputs a string to the main CSV file
+export function benchmark(str: string) {
+  let log_location = process.env["YARN_LOG_PATH"] || "/tmp/yarn.csv";
+  fs.appendFileSync(log_location, str, function(err){if (err) throw err;});
+}
+
+// outputs a string to the debugging log file
+export function debug(str: string) {
+  let log_location = process.env["YARN_DEBUG_PATH"] || "/tmp/debug.log";
+  fs.appendFileSync(log_location, str, function(err){if (err) throw err;});
+}
+
+// post processes the debug log information into a more span-like format
+export function post_process() {
+  let log_location = process.env["YARN_DEBUG_PATH"] || "/tmp/debug.log";
+
+  // run $(column) on data and
+  let results = [];
+  let child = spawn("column", ["-s", "," , "-t", log_location]);
+  results = child.stdout.toString().split("\n");
+  if(!results) { console.error("Make sure column is installed and in $PATH !"); }
+
+  results = results.filter(String);   // remove empty string
+
+  let depth = 1; 
+  results.forEach( function(s, index) {
+
+    // change the indenting (conditional)
+    let indent_depth = depth;
+
+    // BEGIN and END of same process should be on same indent
+    if(results[index].match("END") && results[index-1].match("BEGIN")) {
+      indent_depth = depth - 1;
+      depth--;
+    }
+
+    if(results[index].match("BEGIN") && index > 0 && results[index-1].match("END")) {
+      indent_depth = depth + 1;
+      depth++;
+    }
+
+    results[index] = `(${indent_depth-1})\t` + "    ".repeat(indent_depth-1) + s;
+    results[index] = results[index].replace(/\]\t/, "]\t\t");
+
+    // increase/decrease indent for next line
+    if(s.match("BEGIN")) {
+      depth++;
+    } else if (s.match("END")) {
+      depth--;
+    } else { throw new Error('Regex mismatch !'); }
+  });
+
+  // change BEGIN and END to new separators
+  results.forEach( function(s, index) {
+    results[index] = results[index].replace(/ *(BEGIN|END) */,"^"); 
+  });
+
+  // run $(column) a second time
+  child = spawn("column", ["-s", "^", "-t"], {input: results.join("\n") + "\n"});
+
+  // write output to file
+  fs.writeFileSync(log_location, child.stdout.toString(), function(err){if (err) throw err;});
+
+}

src/reporters/console/console-reporter.js

@@ -22,6 +22,10 @@ import {sortTrees, recurseTree, getFormattedOutput} from './helpers/tree-helper.
 import inquirer from 'inquirer';
 import Table from 'cli-table3';
 
+// STEMN import
+import {benchmark, debug, post_process} from '../../cli/logging.js';
+const fs = require('fs');
+
 const {inspect} = require('util');
 const readline = require('readline');
 const chalk = require('chalk');
@@ -159,20 +163,51 @@ export default class ConsoleReporter extends BaseReporter {
     }
   }
 
+ /* [STEMN]: header reporter. Hook to clean logs */
   header(command: string, pkg: Package) {
     this.log(this.format.bold(`${pkg.name} ${command} v${pkg.version}`));
+
+    if(!process.env.YARN_LOG_PATH) {
+      this._logCategory('LOGGING', 'magenta', "YARN_LOG_PATH env var not found.\tDefaulting to \'/tmp/yarn.csv\'");
+    }
+
+    if(!process.env.YARN_DEBUG_PATH) {
+      this._logCategory('LOGGING', 'magenta', "YARN_DEBUG_PATH env var not found.\tDefaulting to \'/tmp/debug.log\'");
+    }
+
+		// we perform our own reporting as well
+    this._logCategory('LOGGING', 'magenta', "Cleaning logs of previous run...");
+    this._logCategory('LOGGING', 'magenta', "Truncating and preparing log file...");
+    let log_location = process.env["YARN_LOG_PATH"] || "/tmp/yarn.csv";
+    let debug_location = process.env["YARN_DEBUG_PATH"] || "/tmp/debug.log";
+
+    fs.writeFile(log_location, '', function(){})
+    fs.writeFile(debug_location, '', function(){})
+
+    var csv_header = "PID,Command,Timestamp,Duration,PWD\n";
+    fs.writeFileSync(log_location, csv_header, function (err) {
+        if (err) throw err;
+    });
+
   }
 
+/* [STEMN]: footer reporter. Hook to do log post-processing */
   footer(showPeakMemory?: boolean) {
     this.stopProgress();
 
+    let log_location = process.env["YARN_LOG_PATH"] || "/tmp/yarn.csv";
+
     const totalTime = (this.getTotalTime() / 1000).toFixed(2);
     let msg = `Done in ${totalTime}s.`;
     if (showPeakMemory) {
       const peakMemory = (this.peakMemory / 1024 / 1024).toFixed(2);
       msg += ` Peak memory usage ${peakMemory}MB.`;
     }
     this.log(this._prependEmoji(msg, '✨'));
+
+    this._logCategory('LOGGING', 'magenta', "Post-processing logs into suitable format...");
+    post_process();
+    this._logCategory('LOGGING', 'magenta', "Output file: " + this.format.underline(log_location));
   }
 
   log(msg: string, {force = false}: {force?: boolean} = {}) {

src/util/child.js

@@ -6,6 +6,9 @@ import BlockingQueue from './blocking-queue.js';
 import {ProcessSpawnError, ProcessTermError} from '../errors.js';
 import {promisify} from './promise.js';
 
+// STEMN import
+import {benchmark, debug} from '../cli/logging.js';
+
 const child = require('child_process');
 
 export const queue = new BlockingQueue('child', constants.CHILD_CONCURRENCY);
@@ -58,6 +61,7 @@ type ProcessFn = (
   done: () => void,
 ) => void;
 
+/* [STEMN]: Trace for subprocesses ie. script files */
 export function spawn(
   program: string,
   args: Array<string>,
@@ -72,6 +76,26 @@ export function spawn(
         const proc = child.spawn(program, args, opts);
         spawnedProcesses[key] = proc;
 
+        let first_timestamp = (new Date() / 1000);
+        let trace = "";
+        let duration = "-";
+        let cwd = key;
+
+        // if we ever decide to do parent-child relationships
+        // trace += `${process.ppid } spawned ${process.pid} spawned ${proc.pid}`
+
+        trace += `[${proc.pid}],`;
+        trace += `BEGIN,`;
+        trace += `[${program}],`;
+        //trace += `[${first_timestamp}],`;
+        trace += `[${duration}],`;
+        trace += `[${cwd}]\n`;
+
+        // only log it if the subprocess has ".sh"
+        if(program.indexOf(".sh") > -1) {
+          debug(trace);
+        }
+
         let processingDone = false;
         let processClosed = false;
         let err = null;
@@ -95,6 +119,34 @@ export function spawn(
 
         function finish() {
           delete spawnedProcesses[key];
+
+
+          /* [STEMN]: Trace script when finishing execution */
+          let final_timestamp = ((new Date() / 1000)).toFixed(3);
+          let duration = (final_timestamp - first_timestamp).toFixed(3);
+          let trace = "";
+          trace += `[${proc.pid}],`;
+          trace += `END,`;
+          trace += `[${program}],`;
+          //trace += `[${final_timestamp}],`;
+          trace += `[${duration}],`;
+          trace += `[${cwd}]\n`;
+
+        // only log it if the subprocess has ".sh"
+        if(program.indexOf(".sh") > -1) {
+          debug(trace);
+
+          // Add the finished process to the stack for printing
+          let csv_line = "";
+          csv_line += `${proc.pid},`;
+          csv_line += `\"${program}\",`
+          csv_line += `${first_timestamp},`
+          csv_line += `${duration},`
+          csv_line += `\"${key}\"\n`;
+
+          benchmark(csv_line);
+        }
+
           if (err) {
             reject(err);
           } else {

src/util/execute-lifecycle-script.js

@@ -11,6 +11,9 @@ import {registries} from '../resolvers/index.js';
 import {fixCmdWinSlashes} from './fix-cmd-win-slashes.js';
 import {getBinFolder as getGlobalBinFolder, run as globalRun} from '../cli/commands/global.js';
 
+// STEMN import
+import {benchmark, debug} from '../cli/logging.js';
+
 const path = require('path');
 
 export type LifecycleReturn = Promise<{
@@ -356,7 +359,23 @@ export async function execCommand({
   customShell?: string,
 }): Promise<void> {
   const {reporter} = config;
+
+  /* [STEMN]: Trace execCommand start execution time */
+  let first_timestamp = (new Date() / 1000).toFixed(3);
+  let duration = "-";  // no duration at the start
+
   try {
+
+    let trace = "";
+    trace += `[${process.pid}],`;
+    trace += `BEGIN,`;
+    trace += `[${stage}],`;
+    //trace += `[${first_timestamp}],`;
+    trace += `[${duration}],`;
+    trace += `[${cwd}]\n`;
+
+    debug(trace);
+
     reporter.command(cmd);
     await executeLifecycleScript({stage, config, cwd, cmd, isInteractive, customShell});
     return Promise.resolve();
@@ -370,5 +389,31 @@ export async function execCommand({
     } else {
       throw err;
     }
+  } finally {
+
+    /* [STEMN]: Trace execCommand finish exeuction  time */
+
+    //var trace = `[${process.ppid}]->[${process.pid}][${process.uptime()}] >END<`
+
+    let final_timestamp = ((new Date() / 1000).toFixed(3));
+    let duration = (final_timestamp - first_timestamp).toFixed(2);
+    let trace = "";
+    trace += `[${process.pid}],`;
+    trace += `END,`;
+    trace += `[${stage}],`;
+    //trace += `[${final_timestamp}],`;
+    trace += `[${duration}],`;
+    trace += `[${cwd}]\n`;
+
+    debug(trace);
+
+    // PID, STAGE, TIMESTAMP, DURATION, CWD
+    let csv_line = "";
+    csv_line = `${process.pid},`;
+    csv_line += `\"${stage}\",`;
+    csv_line += `${first_timestamp},`;
+    csv_line += `${duration},`;
+    csv_line += `\"${cwd}\"\n`;
+    benchmark(csv_line);
   }
 }