From e2a39823dc3e6cff08ce78a1ae41b1c87cff4e19 Mon Sep 17 00:00:00 2001 From: plocket <52798256+plocket@users.noreply.github.com> Date: Fri, 6 Sep 2024 16:45:24 -0400 Subject: [PATCH] Change log methods signature, use fs.append, add stdout... - Add report_log.txt - Implement action output (untested) - Implement logs in unit tests Co-authored-by: will-morningstar --- action.yml | 12 + lib/scope.js | 10 +- lib/steps.js | 46 +- lib/utils/log.js | 628 ++++++++++++++--------- lib/utils/reports.js | 15 +- tests/unit_tests/getAllFields.test.js | 2 +- tests/unit_tests/getMatchingRows.test.js | 2 +- tests/unit_tests/log.test.js | 20 + tests/unit_tests/normalizeTable.test.js | 2 +- 9 files changed, 464 insertions(+), 273 deletions(-) create mode 100644 tests/unit_tests/log.test.js diff --git a/action.yml b/action.yml index 84b563b0..4da7325a 100644 --- a/action.yml +++ b/action.yml @@ -41,6 +41,9 @@ outputs: PATH_TO_REPORT_FILE: description: 'An empty string ("") or the path to report.txt. Remember to check for the existence of the file before using it.' value: ${{ steps.alkiln_outputs.outputs.PATH_TO_REPORT_FILE }} + PATH_TO_REPORT_LOG_FILE: + description: 'An empty string ("") or the path to report_log.txt. Remember to check for the existence of the file before using it.' + value: ${{ steps.alkiln_outputs.outputs.PATH_TO_REPORT_LOG_FILE }} PATH_TO_UNEXPECTED_RESULTS_FILE: description: 'An empty string ("") or the path to unexpected_results.txt. Remember to check for the existence of the file before using it.' value: ${{ steps.alkiln_outputs.outputs.PATH_TO_UNEXPECTED_RESULTS_FILE }} @@ -175,6 +178,7 @@ runs: else REPORT_PATH="${FOLDER}report.txt" + REPORT_LOG_PATH="${FOLDER}report_log.txt" UNEXPECTED_RESULTS_PATH="${FOLDER}unexpected_results.txt" DEBUG_LOG_PATH="${FOLDER}debug_log.txt" @@ -185,6 +189,13 @@ runs: REPORT_PATH="" fi + if [ -f "$REPORT_LOG_PATH" ]; then + echo "$REPORT_LOG_PATH exists" + else + echo "$REPORT_LOG_PATH is missing" + REPORT_LOG_PATH="" + fi + if [ -f "$UNEXPECTED_RESULTS_PATH" ]; then echo "$UNEXPECTED_RESULTS_PATH exists" else @@ -203,6 +214,7 @@ runs: echo "PATH_TO_ARTIFACTS=$FOLDER" >> "$GITHUB_OUTPUT" echo "PATH_TO_REPORT_FILE=$REPORT_PATH" >> "$GITHUB_OUTPUT" + echo "PATH_TO_REPORT_LOG_FILE=$REPORT_LOG_PATH" >> "$GITHUB_OUTPUT" echo "PATH_TO_UNEXPECTED_RESULTS_FILE=$UNEXPECTED_RESULTS_PATH" >> "$GITHUB_OUTPUT" echo "PATH_TO_DEBUG_LOG_FILE=$DEBUG_LOG_PATH" >> "$GITHUB_OUTPUT" diff --git a/lib/scope.js b/lib/scope.js index cae1f0ea..cc4b2a98 100644 --- a/lib/scope.js +++ b/lib/scope.js @@ -2162,7 +2162,7 @@ module.exports = { * @param ensure_all_vars_used {bool} [false] = Default false. If true, errors if any * object in var_data is not used during running of this function. */ - log.debug({ code: `ALK0219`, before: `~~~~~~~~~~~~~~`, }, + log.debug({ code: `ALK0221`, before: `~~~~~~~~~~~~~~\n`, }, `scope.setFields()` ); @@ -2208,7 +2208,7 @@ module.exports = { // Accumulate number of times this row was used. Esp important for `.target_number` await scope.increment_row_use( scope, { row: row_used }); - process.stdout.write(`\x1b[36m${ '*' }\x1b[0m`); // assumes var was set if no error occurred + log.stdout({}, `\x1b[36m${ '*' }\x1b[0m`); // assumes var was set if no error occurred } } // ends for every non-submit-button field on the page } // ends while fields are still being set @@ -2253,7 +2253,7 @@ module.exports = { // } did_navigate = true; - process.stdout.write(`\x1b[36m${ 'v' }\x1b[0m`); // pressed button successfully + log.stdout({}, `\x1b[36m${ 'v' }\x1b[0m`); // pressed button successfully break; } // ends if row_used @@ -2300,7 +2300,7 @@ module.exports = { // } did_navigate = true; - process.stdout.write(`\x1b[36m${ '>' }\x1b[0m`); // continued successfully + log.stdout({}, `\x1b[36m${ '>' }\x1b[0m`); // continued successfully } // ends if !did_navigate && ensure_navigation if ( did_navigate && scope.check_all_for_a11y ) { @@ -3124,7 +3124,7 @@ module.exports = { } else { // Try to give a random answer for that element tag await scope.set_random_input_for[ field.tag ]( scope, { field: field }); - process.stdout.write(`\x1b[36m${ '*' }\x1b[0m`); // assumes var was set if no error occurred + log.stdout({}, `\x1b[36m${ '*' }\x1b[0m`); // assumes var was set if no error occurred } } // End for all page fields diff --git a/lib/steps.js b/lib/steps.js index 214150e8..1fc12b4b 100644 --- a/lib/steps.js +++ b/lib/steps.js @@ -5,6 +5,7 @@ const { Given, After, Before, + AfterStep, BeforeAll, AfterAll, setDefaultTimeout //, @@ -84,7 +85,7 @@ let click_with = { let log = null; -BeforeAll(async () => { +BeforeAll(async function() { scope.showif_timeout = 600; // TODO: Do these really need to be maps? As sets, they may make the output // more predictable to the user, but they add complexity. @@ -97,21 +98,21 @@ BeforeAll(async () => { // Store path names for files and docs created for the tests scope.paths = {}; - // TODO: figure out how to test file and folder creation stuff, - // especially when setup is excluded from the flow. + // // Make the folder to store all the files for this run of the tests + // scope.paths.artifacts = files.make_artifacts_folder(); + // // Save its name in a file. `session_vars` can get it back later. + // // The value we are saving is used by at least run_cucumber.js. - // Make the folder to store all the files for this run of the tests - scope.paths.artifacts = files.make_artifacts_folder(); - // Save its name in a file. `session_vars` can get it back later. - // The value we are saving is used by at least run_cucumber.js. - session_vars.save_artifacts_path_name( scope.paths.artifacts ); + // A little indirect, but the artifacts path should always have already been + // created by now, either by `run_cucumber.js` or the relevant test + scope.paths.artifacts = session_vars.get_artifacts_path_name(); log = new Log({ path: scope.paths.artifacts, context: `steps` }); scope.set_log({ log_obj: log }); - scope.paths.report = `${ scope.paths.artifacts }/report.txt`; - scope.paths.failures = `${ scope.paths.artifacts }/${ log.unexpected_filename }`; scope.paths.debug_log = `${ scope.paths.artifacts }/${ log.debug_log_filename }`; - fs.writeFileSync( scope.paths.debug_log, "" ); + scope.paths.report_log = `${ scope.paths.artifacts }/${ log.report_log_filename }`; + scope.paths.report = `${ scope.paths.artifacts }/${ log.report_filename }`; + scope.paths.failures = `${ scope.paths.artifacts }/${ log.unexpected_filename }`; reports.create( scope ); }); @@ -119,8 +120,7 @@ BeforeAll(async () => { Before(async (scenario) => { // Start the running "progress bar" for the Scenario - console.log(``); // New line (which stdout doesn't do) - log.stdout({ log: `Scenario: ${ scenario.pickle.name }: ` }) + log.stdout({}, `\nScenario: ${ scenario.pickle.name }: `); // Create browser, which can't be created in BeforeAll() where .driver doesn't exist for some reason if (!scope.browser) { @@ -973,7 +973,7 @@ When(/I answer randomly for at most ([0-9]+) (?:page(?:s)?|screen(?:s)?)/, { tim } // ends if !has_content if ( buttons_exist ) { - process.stdout.write(`\x1b[36m${ 'v' }\x1b[0m`); // pressed button + log.stdout({}, `\x1b[36m${ 'v' }\x1b[0m`); // pressed button } resolve(); @@ -1264,6 +1264,15 @@ Then(/I fail to delete (\d) detected interview(?:s)? and get no error __internal //##################################### //##################################### +AfterStep(async function({ result }) { + // TODO: Abstract this + if ( result.status === `PASSED` ) { log.stdout({ records_only: true }, `.`); } + else if ( result.status === `FAILED` ) { log.stdout({ records_only: true }, `F`); } + else if ( result.status === `UNDEFINED` ) { log.stdout({ records_only: true }, `U`); } + else if ( result.status === `SKIPPED` ) { log.stdout({ records_only: true }, `-`); } + else if ( result.status === `PENDING` ) { log.stdout({ records_only: true }, `P`); } +}); + After(async function(scenario) { // Log errors @@ -1431,6 +1440,13 @@ After(async function(scenario) { need_to_force_failed_status = true; } + // Not sure if this is necessary + if ( changeable_test_status !== 'PASSED' ) { + log.stdout({ records_only: true }, changeable_test_status[0].toUpperCase() ); + } else { + log.stdout({ records_only: true }, `.` ); + } + let signout_succeeded = true; let signout_error_msg = ``; // If there is a page open, then sign out and close it @@ -1526,7 +1542,7 @@ After(async function(scenario) { // Find the race condition. log.debug({ code: `ALK0100`, context: `scenario`, }, - `Scenario AfterStep() message:`, scenario.result.message + `Scenario After() message:`, scenario.result.message ); }); diff --git a/lib/utils/log.js b/lib/utils/log.js index bdf861bb..f7f4155f 100644 --- a/lib/utils/log.js +++ b/lib/utils/log.js @@ -143,22 +143,40 @@ log.unexpected_filename = `unexpected_results.txt`; // =========================== // =========================== +/** + * TODO next: + * - write tests...? + * - edit the decision doc? Too many individual decisions? Separate docs? + * - streams vs. formatter vs. fs.appendFileSync + * - general architecture? + * - keeping report separate for now + * - try/catching everything + collecting errors + * - `throw` (non-standard) + * - `success` (non-standard) + * - + * */ +// + class Log { /** Handles logging to the console and saving to files and reports. * Required argument `{ path }` - the path where the final logs * should be stored. * * Keeps track of its own time differences if we need multiple - * loggers. It's a bit premature. This might not need to be a class. */ + * loggers. It's a bit premature. This might not need to be a class. + * + * We're not using console.Console or write streams because we can't + * control their life cycle during the cucumber tests themselves. + * We can't tell when to properly flush and end the stream in the + * case of a sudden process failure. */ report_filename = `report.txt`; report_log_filename = `report_log.txt`; debug_log_filename = `debug_log.txt`; unexpected_filename = `unexpected_results.txt`; - constructor({ path, context } = {}) {//, filename }) { + constructor({ path, context } = {}) { // this.id = uuid(); - // For elapsed time, see https://nodejs.org/api/console.html#consoletimelabel // Make sure folder exists if ( path ) { files.make_artifacts_folder( path ); } @@ -169,92 +187,77 @@ class Log { this.path = path; session_vars.save_artifacts_path_name( this.path ); - this.add_consoles({ path: this.path }); + // this.add_consoles({ path: this.path }); if ( context ) { context = context + ` log`; } else { context = `log`; } this.info({ code: `ALK0215`, context, }, - `Saving logs at "${ this.path }"` + `Saving files to "${ this.path }"` ); - // if no given folder, make folder - // else if given folder doesn't exist, make folder - // if this name not in runtime_config, save name. Except we - // can't use `session_vars` because of circular reference. - // Maybe that should move to `files` - // Is this the right place for it? Is there a better one? - // Someplace that can use both log and session vars? - // `files`? Then we have saving to config in session_vars - // and `files`... - - // So send path in or create path here? This will, according - // to current plans, be the second thing after session_vars to - // be created every time a process starts. - - // // Report // this.report_path = `${ this.path }/${ this.report_filename }`; // this.report = new Report(); // Indentation? https://nodejs.org/docs/latest-v18.x/api/console.html#consolegrouplabel } - add_consoles({ path }) { - /** Note: These consoles add new lines after each write. - * See https://nodejs.org/docs/latest-v18.x/api/console.html#new-consoleoptions */ - // // This might go in the report obj itself. - // const report_log_stream = fs.createWriteStream( - // // Open stream in "append" mode - // `${ path }/${ this.report_log_filename }`, { flags: `a` } - // ); - // this.report_console = new console.Console({ - // stdout: report_log_stream, stderr: report_log_stream, - // }); - - this.streams = []; - - // debug log - const debug_log_stream = this.debug_log_stream = fs.createWriteStream( - // Open stream in "append" mode - `${ path }/${ this.debug_log_filename }`, { flags: `a` } - ); - this.debug_console = new console.Console({ - stdout: debug_log_stream, stderr: debug_log_stream, - }); - this.streams.push( debug_log_stream ); - - // TODO: report log - // TODO: unexpected log? - - this.streams_promises = []; - - // Add promises and their listeners so we can close up properly at the end - for ( let stream of this.streams ) { - this.streams_promises.push( new Promise((end_with, throw_with) => { - stream.once(`close`, end_with).once(`error`, throw_with); - }) ); - } - } + // add_consoles({ path }) { + // /** Note: These consoles add new lines after each write. + // * See https://nodejs.org/docs/latest-v18.x/api/console.html#new-consoleoptions */ + // // // This might go in the report obj itself. + // // const report_log_stream = fs.createWriteStream( + // // // Open stream in "append" mode + // // `${ path }/${ this.report_log_filename }`, { flags: `a` } + // // ); + // // this.report_console = new console.Console({ + // // stdout: report_log_stream, stderr: report_log_stream, + // // }); + + // this.streams = []; + + // // debug log + // const debug_log_stream = this.debug_log_stream = fs.createWriteStream( + // // Open stream in "append" mode + // `${ path }/${ this.debug_log_filename }`, { flags: `a` } + // ); + // this.debug_console = new console.Console({ + // stdout: debug_log_stream, stderr: debug_log_stream, + // }); + // this.streams.push( debug_log_stream ); + + // // TODO: report log + // // TODO: unexpected log? + + // this.streams_promises = []; + + // // Add promises and their listeners so we can close up properly at the end + // for ( let stream of this.streams ) { + // this.streams_promises.push( new Promise((end_with, throw_with) => { + // stream.once(`close`, end_with).once(`error`, throw_with); + // }) ); + // } + // } async with_cleanup({ todo }) { - try { + // try { await todo(); - await this.clean_up(); - } catch ( error ) { - await this.clean_up(); - throw error; - } + // await this.clean_up(); + // } catch ( error ) { + // await this.clean_up(); + // throw error; + // } } - async clean_up() { - /** Make sure all the log's streams end cleanly */ - // End every stream. The listeners are already listening - for ( let stream of this.streams ) { - stream.end(); - } - // Wait for all streams to finish closing - await Promise.all(this.streams_promises); - return this; - } + // async clean_up() { + // /** Make sure all the log's streams end cleanly */ + // // End every stream. The listeners are already listening + // for ( let stream of this.streams ) { + // stream.end(); + // } + // // Wait for all streams to finish closing + // await Promise.all(this.streams_promises); + // return this; + // } console( console_opts = {}, ...logs ) { /** Log the logs to the console at the right level and with the metadata. @@ -291,46 +294,16 @@ class Log { * { code: `123`, context: `setup internal`, error: error }, * ); * - * Note: Sometimes there's just one log - * - * Example: - * - * Log = require('./lib/utils/log.js') - * log = new Log('_alkiln-') - * - * log.console(); - * // ? ALK000c console LOG [2024-08-16 00:30:39UTC]: - * - log.console({ - level: `info`, - icon: `&&&`, - code: `ALK00t1`, - context: `a test`, - }, `test info log`); - - try { - let czar = zoo + 5; - } catch ( error ) { - log.console({ - level: `error`, - before: `===\n===\n`, - icon: `X` - code: `ALK00t2` - context: `err_test` - error: new Error(`This is an error`), - }, `error test log 1`, `error test log 2`) - } - * * */ // This creates kind of a weird signature... let { // Defaults level = `log`, before = ``, // different name? above? start_decorator? - icon = `?`, + icon = `*`, code = `ALK000c`, context = ``, - // logs = [], - error = null + error = null, + do_throw = false, } = console_opts; let with_error = [...logs]; @@ -339,40 +312,47 @@ class Log { } let formatted_log = this.debug({ level, before, icon, code, context }, ...with_error ); - // Shame to do this in .debug too, but haven't found a - // better way to return consistent values otherwise. + // better way to return consistent values otherwise. We + // want other logs to be logged by the console in its way. const metadata = this._format_metadata({ level, icon, code, context }); - // Throw an 'error' error - if ( level === `error` && error !== null ) { - // Log before error - console.log( before ); + // Throw whatever we can throw + if ( do_throw ) { let custom_msg = this._stringify_logs({ logs: [ metadata, ...logs ] }); - console.log( custom_msg); if ( error instanceof Error ) { + console.log( before + custom_msg ); throw error; - } else { + } else if ( error !== null ) { + console.log( before + custom_msg ); throw new Error( error ); + } else { + console.log( before ); // Adds extra new line, unfortunately + throw new Error( custom_msg ); } } try { // Otherwise, log at the given level if console has that method (`log` by default) + // If a non-standard level was passed in, like `success`, use `info` by default if ( console[ level ]) { - // Potentially: console[ level ].apply(this, before + metadata, ...logs ); console[ level ]( before + metadata, ...with_error ); } else { - // If a non-standard level was passed in, like `success`, use `info` by default console.info( before + metadata, ...with_error ); } } catch ( console_log_error ) { - // Fail silently for now - this.debug({ - level: `error`, icon: `🤕`, code: `ALK0211`, - context: `internal`, - error: console_log_error - }, `Tried to console.${ level } the message above`); + // Fail silently + // (TODO: try/catch) + // Gather errors? + try { + this.debug({ + level: `warn`, icon: `🔎`, code: `ALK0211`, + context: `internal`, + error: console_log_error + }, `Skipped logging a message with console.${ level }()`); + } catch ( console_debug_error ) { + console.warn( `🔎 ALK0217 internal WARNING: Skipped the same log two times consecutively`, console_debug_error, console_log_error ); + } } finally { return formatted_log; } @@ -381,12 +361,13 @@ class Log { debug( debug_opts = {}, ...logs ) { /** Save in the debug log file and return a string version * of the log. If there are errors, just log them too. - * Keep as much info from the caller as possible. + * Keep as much info from the caller as possible. Avoid throwing + * errors if at all possible while giving the max info possible. * * Example: * * Log = require('./lib/utils/log.js') - * log = new Log('_alkiln-') + * log = new Log({ path: '_alkiln-' }) * log.debug() * // 🐛 ALK000v debug DEBUG [2024-08-16 00:38:49UTC]: * */ @@ -396,61 +377,103 @@ class Log { icon = `🐛`, code = `ALK000v`, context = ``, - // logs = [], error = null, } = debug_opts; + // function stackTrace() { return (new Error()).stack; } + // and + // https://stackoverflow.com/a/41820537/14144258 + // var mystring=require('util').inspect(error_object); + + let logging_errors = []; + + // Get a proper error log if needed + if ( level === `throw` ) { level = `error`; } + + let metadata = `No metadata: `; + try { + metadata = this._format_metadata({ level, icon, code, context }); + } catch ( metadata_error ) { + // Consider using `util.inspect()` for the error + logging_errors.push(`🔎 ALK0212 internal WARNING: Skipped creating debug metadata\n${ metadata_error.stack }`); + } + // Include error as the last log - let metadata = `Unexpected debug metadata`; let with_error = [...logs]; if ( error ) { with_error.push( error ); } - let console_log_error = false; + let formatted_log = `${ metadata }No formatted log.`; try { - // Should we split formatting and saving to file into their own errors? - metadata = this._format_metadata({ level, icon, code, context }); - if ( console[ level ]) { // `debug` if caller left it blank - this.debug_console[ level ]( before + metadata, ...with_error ); - } else { - this.debug_console.info( before + metadata, ...with_error ); - } - } catch ( debug_console_log_error ) { - console_log_error = true; - console.warn( `🔎 ALK0212 internal WARNING: Unexpected behavior with log.debug_console`, debug_console_log_error ); + let stringified = this._stringify_logs({ logs: with_error }); + formatted_log = `${ before }${ metadata }${ stringified }`; + } catch ( formatted_log_error ) { + // Consider using `util.inspect()` for the error + logging_errors.push(`🔎 ALK0213 internal WARNING: Skipped creating full debug log\n${ formatted_log_error.stack }`); } - // Formatting the whole log will get its own catch - let formatted_log = `Could not create any log info.`; + let fs_append_failed = false; try { - formatted_log = `${ before }${ metadata }\n` - + `${ this._stringify_logs({ logs: with_error }) }`; - - } catch ( formatting_error ) { - console.warn( `🔎 ALK0213 internal WARNING: Unexpected behavior formatting log in log.debug`, formatting_error ); - formatted_log = this._try_to_return_something({ - level, before, icon, code, context, logs, error - }); + fs.appendFileSync( `${ this.path }/${ this.debug_log_filename }`, `\n` + formatted_log ) + } catch ( fs_append_error ) { + fs_append_failed = true; + // Consider using `util.inspect()` for the error + logging_errors.push(`🔎 ALK0214 internal WARNING: Could not append to debug log file\n${ fs_append_error.stack }`); } - if ( console_log_error ) { - try { - fs.appendFileSync( - `${ this.path }/${ this.debug_log_filename }`, - formatted_log - ); - } catch ( fs_append_error ) { - console.warn( `🔎 ALK0217 internal WARNING: Unexpected behavior with fs.appendFileSync`, fs_append_error ); + // Record any errors in the most unobtrusive way possible + if ( logging_errors.length > 0 ) { + for ( let logging_error of logging_errors ) { + if ( fs_append_failed ) { + console.warn( logging_error ); + } else { + fs.appendFileSync( `${ this.path }/${ this.debug_log_filename }`, `\n` + logging_error ); + } } } return formatted_log; + + // try { + // // Should we split formatting and saving to file into their own errors? + // metadata = this._format_metadata({ level, icon, code, context }); + + // // Formatting the whole log will get its own catch + // try { + // formatted_log = `${ before }${ metadata }` + // + `${ this._stringify_logs({ logs: with_error }) }`; + + // } catch ( formatting_error ) { + // console.warn( `🔎 ALKx0213 internal WARNING: Unexpected behavior formatting log in log.debug`, formatting_error ); + // formatted_log = this._try_to_return_some_log_string({ + // level, before, icon, code, context, logs, error + // }); + // } + // fs.appendFileSync( `${ this.path }/${ this.debug_log_filename }`, `\n` + formatted_log ); + // } catch ( debug_console_log_error ) { + // log_error = true; + // console.warn( `🔎 ALKx0212 internal WARNING: Unexpected behavior with log.debug`, debug_console_log_error ); + // } + + // // TODO + // if ( log_error ) { + // try { + // fs.appendFileSync( + // `${ this.path }/${ this.debug_log_filename }`, + // formatted_log + // ); + // } catch ( fs_append_error ) { + // console.warn( `🔎 ALKx0217 internal WARNING: Unexpected behavior with fs.appendFileSync`, fs_append_error ); + // } + // } + + // return formatted_log; } _format_metadata( metadata_opts = {} ) { /** Format and return the log metadata. - * Example: 💡 ALK### internal INFO [10:24:40 pm UTC] something: + * Example: "💡 ALK#### internal INFO [10:24:40 pm UTC]: " * */ let { level=`log`, @@ -459,17 +482,34 @@ class Log { context = ``, } = metadata_opts; - let metadata = `? ALK000m unspecified` + let metadata = `? ALK000m unspecified: `; try { let metadata_level = level; if ( level === `warn` ) { metadata_level = `warning`; } let level_caps = metadata_level.toUpperCase(); // For elapsed time, see https://nodejs.org/api/console.html#consoletimelabel // Should this really be a pretty date, or should it be a raw timestamp? - let metadata_list = [ icon, code, context, level_caps, `[${ time.log_date() }]` ]; - metadata = metadata_list.join(` `) + `:`; + + // let metadata_list = [ icon, code, context, level_caps, `[${ time.log_date() }]` ]; + // let metadata_list = [ icon, code, context, level_caps, `[${ time.log_date() }]` ].filter(function ( item ) { + // return item !== ``; + // }).join(` `) + `: `; + + let metadata_list = []; + for ( let item of [ icon, code, context, level_caps, `[${ time.log_date() }]` ]) { + if ( item !== `` ) { metadata_list.push(item); } + } + metadata = metadata_list.join(` `) + `: `; } catch ( in_metadata_error ) { - console.warn( `${ metadata }: Unexpected behavior creating metadata` ); + let msg = `Skipped creating metadata`; + code = `ALK0220`; + icon = `🔎`; + context = `internal logs metadata`; + try { + this.debug({ icon, level: `warn`, code, context }, msg ); + } catch { + console.warn( `${ icon } ${ code } ${ context } WARNING [${ Date.now() }]: ${ msg }`, in_metadata_error ); + } } return metadata; } @@ -484,86 +524,101 @@ class Log { let stringified_logs = ``; let prev_line_type = null; - for ( let log of logs ) { - if ( log === null || [`string`, `number`, `undefined`, `boolean`].includes( typeof(log) )) { - - stringified_logs += this._stringify_inline({ prev_line_type, log }); - prev_line_type = `inline`; - - } else if ( log instanceof Error ) { - // A block of text (the error stack) always starts on a new line. - // Node error stack seems to have all the necessary info. - stringified_logs += `\n${ log.stack }`; - prev_line_type = `block`; - - } else { - stringified_logs += this._stringify_object({ obj: log }); - prev_line_type = `block`; - } // ends typeof log - } // Ends for logs - - return stringified_logs; - } - - _try_to_return_something({ - level, before, icon, code, context, logs, error, - }) { - /** Logging had an error. Try building simpler and simpler - * output in the hope of returning anything useful. At worst, - * return a final error and return something generic. */ - let final_error = ''; - - // One by one, try returning whatever it's possible to return - try { - // Something wrong with the logic of the code before this? - let data = [ level, before, icon, code, context, logs, error ]; - return this._if_succeed_log_final_error({ data, final_error }); - } catch ( internal_try_to_return_error2 ) { - final_error = internal_try_to_return_error2; - } - - try { - // Something wrong with the `error` object? - let data = [ level, before, icon, code, context, logs ]; - return this._if_succeed_log_final_error({ data, final_error }); - } catch ( internal_try_to_return_error3 ) { - final_error = internal_try_to_return_error3; - } - try { - // Something wrong with the `logs` object? - let data = [ level, before, icon, code, context, error ]; - return this._if_succeed_log_final_error({ data, final_error }); - } catch ( internal_try_to_return_error4 ) { - final_error = internal_try_to_return_error4; - } + for ( let log of logs ) { + // TODO: Try/catch each of these? + if ( log === null || [`string`, `number`, `undefined`, `boolean`].includes( typeof(log) )) { + + stringified_logs += this._stringify_inline({ prev_line_type, log }); + prev_line_type = `inline`; + + } else { + // For objects and errors + stringified_logs += this._stringify_object({ obj: log }); + prev_line_type = `block`; + } // ends typeof log + } // Ends for logs + } catch ( stringify_error ) { + // TODO: Should `stringify_error` get recorded even when util.inspect works? + try { + stringified_logs = util.inspect( logs, { depth: 8, maxArrayLength: null, maxStringLength: null, }); + } catch ( util_error ) { - try { - // Something wrong with both? These should all be strings - // and we can't check absolutely every combination - let data = [ level, before, icon, code, context ]; - return this._if_succeed_log_final_error({ data, final_error }); - } catch ( internal_try_to_return_error5 ) { - final_error = internal_try_to_return_error5; + if ( stringified_logs ) { + stringified_logs += `Unable to stringify logs. Got:\n${ stringified_logs }\n${ util_error.trace }\n${ stringify_error }`; + } else { + stringified_logs = `Unable to stringify logs.\n${ util_error.trace }\n${ stringify_error }`; + } + // let fallback_logs = `Unable to stringify logs. `; + // if ( stringified_logs ) { + // fallback_logs += `Got: ${ stringified_logs }`; + // } + // fallback_logs += `\n${ util_error.trace }`; + } } - // Still throwing errors? We did the best we could - console.warn( final_error ); - return `🔎 ALK0214 internal WARNING: Unable to return any logs. Error: ${ final_error }`; - } + return stringified_logs; + } // Ends Log._stringify_logs() + + // _try_to_return_some_log_string({ + // level, before, icon, code, context, logs, error, + // }) { + // /** Logging had an error. Try building simpler and simpler + // * output in the hope of returning anything useful. At worst, + // * return a final error and return something generic. */ + // let final_error = ''; + + // // One by one, try returning whatever it's possible to return + // try { + // // Something wrong with the logic of the code before this? + // let data = [ level, before, icon, code, context, logs, error ]; + // return this._if_succeed_log_final_error({ data, final_error }); + // } catch ( internal_try_to_return_error2 ) { + // final_error = internal_try_to_return_error2; + // } + + // try { + // // Something wrong with the `error` object? + // let data = [ level, before, icon, code, context, logs ]; + // return this._if_succeed_log_final_error({ data, final_error }); + // } catch ( internal_try_to_return_error3 ) { + // final_error = internal_try_to_return_error3; + // } + + // try { + // // Something wrong with the `logs` object? + // let data = [ level, before, icon, code, context, error ]; + // return this._if_succeed_log_final_error({ data, final_error }); + // } catch ( internal_try_to_return_error4 ) { + // final_error = internal_try_to_return_error4; + // } + + // try { + // // Something wrong with both? These should all be strings + // // and we can't check absolutely every combination + // let data = [ level, before, icon, code, context ]; + // return this._if_succeed_log_final_error({ data, final_error }); + // } catch ( internal_try_to_return_error5 ) { + // final_error = internal_try_to_return_error5; + // } + + // // Still throwing errors? We did the best we could + // console.warn( final_error ); + // return `🔎 ALKx0214 internal WARNING: Unable to return any logs. Error: ${ final_error }`; + // } - _if_succeed_log_final_error({ data, final_error }) { - /** There was a problem. If we can stringify this data, - * we found the problem - it was the last thing we tried - - * so log what broke and return what works. Otherwise, - * there is still a problem and this will error correctly. */ - // util.inspect can handle circular references - let working_stringified_value = util.inspect( data, { depth: 8, maxArrayLength: null, maxStringLength: null, }); - // If stringifying failed, we won't get here. If it succeeded, - // we're done, so we can return a useful error. - console.warn( final_error ); - return working_stringified_value; - } + // _if_succeed_log_final_error({ data, final_error }) { + // /** There was a problem. If we can stringify this data, + // * we found the problem - it was the last thing we tried - + // * so log what broke and return what works. Otherwise, + // * there is still a problem and this will error correctly. */ + // // util.inspect can handle circular references + // let working_stringified_value = util.inspect( data, { depth: 8, maxArrayLength: null, maxStringLength: null, }); + // // If stringifying failed, we won't get here. If it succeeded, + // // we're done, so we can return a useful error. + // console.warn( final_error ); + // return working_stringified_value; + // } _stringify_inline({ prev_line_type, log }) { /** Format an inline log. Mostly involves fiddling with @@ -579,17 +634,17 @@ class Log { } _stringify_object({ obj }) { - /** Try to stringify an object a few different ways. + /** Try to stringify an object a few different ways. Works for + * errors too. * TODO: discuss using https://nodejs.org/docs/latest-v18.x/api/util.html#utilinspectobject-options. */ try { // A block of text (the object) always starts on a new line // Try to stringify the object. - // return `\n${ JSON.stringify( obj, null, 2 ) }`; - return `\n${ util.inspect( obj ), { depth: 8, maxArrayLength: null, maxStringLength: null, } }`; + return `\n${ util.inspect( obj, { depth: 8, maxArrayLength: null, maxStringLength: null, } )}`; } catch ( outer_error ) { // If that fails, see if it has its own way of stringifying try { - return `${ obj }`; + return `\n${ obj }`; } catch ( inner_error ) { // Lastly, give at least some information return `\nUnable to log this ${ typeof obj }`; @@ -599,6 +654,8 @@ class Log { success( success_opts = {}, ...logs ) { /** Console log success - log level with success icon. */ + // Discuss: do we want to log some successes as "💡 ... SUCCESS: "? + // Should we allow callers to override levels and icons? let { code = `ALK000s`, before = ``, context = `` } = success_opts; @@ -650,7 +707,7 @@ class Log { * The `error` option is required. */ let { code = `ALK000t`, before = ``, context = ``, - error + do_throw = true, error, } = throw_opts; return this.console({ level: `error`, icon: `🤕`, @@ -659,17 +716,96 @@ class Log { } unexpected({ text = `` } = {}) { - fs.appendFileSync(`${ this.path }/${ this.unexpected_filename }`, text ); + fs.appendFileSync(`${ this.path }/${ this.unexpected_filename }`, `\n${ text }` ); + } + + // stdout({ log = `` } = {}) { + // /** Prints in the console inline. How do we get these in + // * the debug logs? */ + // process.stdout.write( log ); + // // Also write it to the report and the debug log + // return log; + // } + + stdout(stdout_opts = {}, ...logs) { + /** Prints in the console inline and saves to + * the debug log and the report log. */ + let { + records_only = false, + } = stdout_opts; + let whole_log = logs.join(` `); + + // Always write to debug somehow - inline? new line? + // Always write to the report in a new section at the top + this._record_stdout({ logs }); + + if ( records_only ) { + // don't write to the console + } else { + process.stdout.write( whole_log ); + } + + return logs; } - stdout({ log = `` } = {}) { - /** Prints in the console inline. How do we get these in - * the debug logs? */ - process.stdout.write( log ); - // Also write it to the report and the debug log - return log; + _record_stdout({ logs = [] }) { + /***/ + this.debug({ code: `ALK0219`, context: `stdout` }, ...logs); + let whole_log = logs.join(` `); + fs.appendFileSync( `${ this.path }/${ this.report_log_filename }`, whole_log ); + // TODO: write to report after metadata + } + + clear() { + /** Empty all files possible. Mostly for testing. */ + try { fs.writeFileSync( `${ this.path }/${ this.debug_log_filename }`, `` ); } + catch (error) { /* Do nothing, no file there or something */ } + try { fs.writeFileSync( `${ this.path }/${ this.report_log_filename }`, `` ); } + catch (error) { /* Do nothing, no file there or something */ } + try { fs.writeFileSync( `${ this.path }/${ this.report_filename }`, `` ); } + catch (error) { /* Do nothing, no file there or something */ } + try { fs.writeFileSync( `${ this.path }/${ this.unexpected_filename }`, `` ); } + catch (error) { /* Do nothing, no file there or something */ } } } // Ends Log{} module.exports = Log; + +/** + * TODO: + * - [ ] maintain old debug log? (what did this mean?) + * - [x] actions debug_log -> report_log + * - [x] actions verbose_log -> debug_log + * - [ ] stdout.write() + * + * + * Note: Sometimes there's just one log + * + * Example: + * + * Log = require('./lib/utils/log.js') + * log = new Log('_alkiln-') + * + * log.console(); + * // ? ALK000c console LOG [2024-08-16 00:30:39UTC]: + * + log.console({ + level: `info`, + icon: `&&&`, + code: `ALK00t1`, + context: `a test`, + }, `test info log`); + + try { + let czar = zoo + 5; + } catch ( error ) { + log.console({ + level: `error`, + before: `===\n===\n`, + icon: `X` + code: `ALK00t2` + context: `err_test` + error: new Error(`This is an error`), + }, `error test log 1`, `error test log 2`) + }*/ diff --git a/lib/utils/reports.js b/lib/utils/reports.js index e3f57348..b4da8105 100644 --- a/lib/utils/reports.js +++ b/lib/utils/reports.js @@ -66,16 +66,20 @@ reports.addToReport = function( scope, { type, code, value }) { const MISC_ARTIFACTS_DIR = `_alkiln-misc_artifacts`; if ( !scope.paths ) { // Can this be usefully abstracted? - scope.paths = { debug_log: `${ MISC_ARTIFACTS_DIR }/unit_tests_logs-${ files.readable_date() }.txt` }; + let date = files.readable_date(); + scope.paths = { + debug_log: `${ MISC_ARTIFACTS_DIR }/unit_tests_debug_log-${ date }.txt`, + report_log: `${ MISC_ARTIFACTS_DIR }/unit_tests_report_log-${ date }.txt`, + }; } - // log.log(data); - try { fs.appendFileSync( scope.paths.debug_log, `\nReport:\n${debug_line}` ); - } catch ( err ) { + fs.appendFileSync( scope.paths.report_log, `\nReport:\n${debug_line}` ); + } catch ( file_error ) { fs.mkdirSync( MISC_ARTIFACTS_DIR ); fs.appendFileSync( scope.paths.debug_log, `\nReport:\n${debug_line}` ); + fs.appendFileSync( scope.paths.report_log, `\nReport:\n${debug_line}` ); // An error in here should throw (for now) } @@ -136,6 +140,9 @@ reports.saveFinalScenarioData = function( scope, { status=`in progress` }) { return scenario; }; // Ends reports.saveFinalScenarioData() +reports.progress = function ({ logs=[] }) { + // TODO: save stdout-style to report_log, object, and getting printable scenario +}; reports.setReportScenarioStatus = function( scope, { status=`PASSED` }) { /** Add final status of scenario to scenario report object - passed, failed, etc. */ diff --git a/tests/unit_tests/getAllFields.test.js b/tests/unit_tests/getAllFields.test.js index 78310195..5daa0c71 100644 --- a/tests/unit_tests/getAllFields.test.js +++ b/tests/unit_tests/getAllFields.test.js @@ -9,7 +9,7 @@ const fields = require('./fields.fixtures.js'); const scope = require('../../lib/scope.js'); const Log = require(`../../lib/utils/log.js`); -const log = new Log({ context: `unit_tests getAllFields` }); +const log = new Log({ path: `_alkiln-misc_artifacts`, context: `unit_tests getAllFields` }); scope.set_log({ log_obj: log }); const getAllFields = scope.getAllFields; diff --git a/tests/unit_tests/getMatchingRows.test.js b/tests/unit_tests/getMatchingRows.test.js index 4098bc07..74af49b2 100644 --- a/tests/unit_tests/getMatchingRows.test.js +++ b/tests/unit_tests/getMatchingRows.test.js @@ -8,7 +8,7 @@ const matches = require('./matches.fixtures.js'); const scope = require('../../lib/scope.js'); const Log = require(`../../lib/utils/log.js`); -const log = new Log({ context: `unit_tests getMatchingRows` }); +const log = new Log({ path: `_alkiln-misc_artifacts`, context: `unit_tests getMatchingRows` }); scope.set_log({ log_obj: log }); const getMatchingRows = scope.getMatchingRows; diff --git a/tests/unit_tests/log.test.js b/tests/unit_tests/log.test.js new file mode 100644 index 00000000..af83fa32 --- /dev/null +++ b/tests/unit_tests/log.test.js @@ -0,0 +1,20 @@ +const chai = require('chai'); +const expect = chai.expect; + +const Log = require('../../lib/utils/log.js'); + +const path = `_alkiln-misc_artifacts`; +const log = new Log({ path, context: `unit_tests log_tests` }); + +describe(`log`, async function () { + + // Test it creates a new folder? + // Test the contents that it saves to various files? + + it(`returns a debug message from an empty log.debug`, async function() { + let result = log.debug(); + expect( result ).to.include( `🐛 ALK000v DEBUG` ); + }); + +}); + diff --git a/tests/unit_tests/normalizeTable.test.js b/tests/unit_tests/normalizeTable.test.js index cd71b22f..8042768b 100644 --- a/tests/unit_tests/normalizeTable.test.js +++ b/tests/unit_tests/normalizeTable.test.js @@ -7,7 +7,7 @@ const tables = require('./tables.fixtures.js'); const scope = require('../../lib/scope.js'); const Log = require(`../../lib/utils/log.js`); -const log = new Log({ context: `unit_tests normalizeTable` }); +const log = new Log({ path: `_alkiln-misc_artifacts`, context: `unit_tests normalizeTable` }); scope.set_log({ log_obj: log }); const normalizeTable = scope.normalizeTable;