WIP: Jaeger Tracing

.travis.yml

@@ -0,0 +1,20 @@
+language: bash
+
+services:
+  - docker
+
+script:
+  # Build the deb package in the yarn development container
+  - docker run -v $PWD:$PWD -w $PWD yarnpkg/dev:latest /bin/sh -c "yarn && yarn build-dist && scripts/build-deb.sh"
+
+  # Install gcloud so we can upload the build to our bucket
+  - if [ ! -d "$HOME/google-cloud-sdk/bin" ]; then rm -rf $HOME/google-cloud-sdk; export CLOUDSDK_CORE_DISABLE_PROMPTS=1; curl https://sdk.cloud.google.com | bash; fi
+  - source /home/travis/google-cloud-sdk/path.bash.inc
+  - gcloud version
+
+  # Authenticate
+  - echo $GOOGLE_CREDENTIALS_BASE64 | base64 -d > credentials.json
+  - gcloud auth activate-service-account --key-file=credentials.json
+
+  # Upload the built snap file
+  - gsutil cp artifacts/*.deb $GOOGLE_BUCKET/stemn-yarn.deb

README.md

@@ -16,6 +16,26 @@
   <a href="http://commitizen.github.io/cz-cli/"><img alt="Commitizen friendly" src="https://img.shields.io/badge/commitizen-friendly-brightgreen.svg"></a>
 </p>
 
+<p align="center">
+  <b>With Jaeger and CLI Tracing for Visualizing Cloud Computer Operations</b>
+</p>
+
+<p align="center">
+  <img alt="CLI Tracing" src="https://github.com/kawing-ho/kawing-ho.github.io/blob/master/assets/images/startup-yarn-2.png?raw=true">
+</p>
+<p align="center">
+  <i>Cloud Computer Packer Image Creation Jaeger Trace</i>
+</p>
+
+<p></p>
+
+<p align="center">
+  <img alt="CLI Tracing" src="https://github.com/kawing-ho/kawing-ho.github.io/blob/master/assets/images/startup-ascii.jpg?raw=true">
+</p>
+<p align="center">
+  <i>Cloud Computer Packer Image Creation CLI Trace</i>
+</p>
+
 ---
 
 **Fast:** Yarn caches every package it has downloaded, so it never needs to download the same package again. It also does almost everything concurrently to maximize resource utilization. This means even faster installs.

package.json

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

src/cli/index.js

@@ -25,6 +25,8 @@ import {version} from '../util/yarn-version.js';
 import handleSignals from '../util/signal-handler.js';
 import {boolify, boolifyWithDefault} from '../util/conversion.js';
 
+import {benchmark, debug} from './logging.js';
+
 function findProjectRoot(base: string): string {
   let prev = null;
   let dir = base;
@@ -246,6 +248,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 +287,10 @@ export async function main({
       if (shouldWrapOutput) {
         reporter.footer(false);
       }
+
+      /* Possible hook here for exitCode conditional code */
+
+
       return exitCode;
     });
   };
@@ -478,6 +486,8 @@ export async function main({
     if (errorReportLoc) {
       reporter.info(reporter.lang('bugReport', errorReportLoc));
     }
+
+    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,9 @@ import {sortTrees, recurseTree, getFormattedOutput} from './helpers/tree-helper.
 import inquirer from 'inquirer';
 import Table from 'cli-table3';
 
+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 +162,51 @@ export default class ConsoleReporter extends BaseReporter {
     }
   }
 
+  // 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;
+    });
+
   }
 
+  // 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/reporters/lang/en.js

@@ -179,7 +179,7 @@ const messages = {
     'You can now run `yarn unlink $0` in the projects where you no longer want to use this package.',
   linkUsing: 'Using linked package for $0.',
   linkDisusing: 'Removed linked package $0.',
-  linkDisusingMessage: 'You will need to run `yarn install --force` to re-install the package that was linked.',
+  linkDisusingMessage: 'You will need to run `yarn` to re-install the package that was linked.',
   linkTargetMissing: 'The target of linked package $0 is missing. Removing link.',
 
   createInvalidBin: 'Invalid bin entry found in package $0.',

src/util/child.js

@@ -6,6 +6,8 @@ import BlockingQueue from './blocking-queue.js';
 import {ProcessSpawnError, ProcessTermError} from '../errors.js';
 import {promisify} from './promise.js';
 
+import {benchmark, debug} from '../cli/logging.js';
+
 const child = require('child_process');
 
 export const queue = new BlockingQueue('child', constants.CHILD_CONCURRENCY);
@@ -58,6 +60,7 @@ type ProcessFn = (
   done: () => void,
 ) => void;
 
+// Trace for subprocesses
 export function spawn(
   program: string,
   args: Array<string>,
@@ -72,6 +75,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 +118,34 @@ export function spawn(
 
         function finish() {
           delete spawnedProcesses[key];
+
+
+          /* Trace subprocess 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,8 @@ 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';
 
+import {benchmark, debug} from '../cli/logging.js';
+
 const path = require('path');
 
 export type LifecycleReturn = Promise<{
@@ -356,7 +358,23 @@ export async function execCommand({
   customShell?: string,
 }): Promise<void> {
   const {reporter} = config;
+
+  // 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 +388,31 @@ export async function execCommand({
     } else {
       throw err;
     }
+  } finally {
+
+    // 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);
   }
 }