diff --git a/package.json b/package.json index 8b7e9fffcd..aa66bcec96 100644 --- a/package.json +++ b/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.", diff --git a/src/cli/index.js b/src/cli/index.js index a4b307d57a..afd5c87dff 100644 --- a/src/cli/index.js +++ b/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 { diff --git a/src/cli/logging.js b/src/cli/logging.js new file mode 100644 index 0000000000..1467545e11 --- /dev/null +++ b/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;}); + +} diff --git a/src/reporters/console/console-reporter.js b/src/reporters/console/console-reporter.js index 0fe162788c..748a3f6222 100644 --- a/src/reporters/console/console-reporter.js +++ b/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,13 +163,40 @@ 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) { @@ -173,6 +204,10 @@ export default class ConsoleReporter extends BaseReporter { 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} = {}) { diff --git a/src/util/child.js b/src/util/child.js index e83b819745..52d7d20ab4 100644 --- a/src/util/child.js +++ b/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, @@ -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 { diff --git a/src/util/execute-lifecycle-script.js b/src/util/execute-lifecycle-script.js index aae9a2d09d..8922111724 100644 --- a/src/util/execute-lifecycle-script.js +++ b/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 { 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); } }