Merge pull request #448 from HeyPuter/eric/log-update

feat(backend): improve logger and reduce logs

package-lock.json

@@ -6,13 +6,14 @@
   "packages": {
     "": {
       "name": "puter.com",
-      "version": "1.0.0",
+      "version": "2.3.0",
       "hasInstallScript": true,
       "license": "AGPL-3.0-only",
       "workspaces": [
         "packages/*"
       ],
       "dependencies": {
+        "json-colorizer": "^3.0.1",
         "uuid": "^9.0.1"
       },
       "devDependencies": {
@@ -7956,6 +7957,19 @@
       "integrity": "sha512-4bV5BfR2mqfQTJm+V5tPPdf+ZpuhiIvTuAB5g8kcrXOZpTT/QwwVRWBywX1ozr6lEuPdbHxwaJlm9G6mI2sfSQ==",
       "dev": true
     },
+    "node_modules/json-colorizer": {
+      "version": "3.0.1",
+      "resolved": "https://registry.npmjs.org/json-colorizer/-/json-colorizer-3.0.1.tgz",
+      "integrity": "sha512-4YyRAbD6eHeRnJD9vo0zjiU5fyY9QR6T+iYuH5DpO0XPThKWozpD4MaeY/8nLZIkHC3yEQMFLL+6P94E+JekDw==",
+      "dependencies": {
+        "colorette": "^2.0.20"
+      }
+    },
+    "node_modules/json-colorizer/node_modules/colorette": {
+      "version": "2.0.20",
+      "resolved": "https://registry.npmjs.org/colorette/-/colorette-2.0.20.tgz",
+      "integrity": "sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w=="
+    },
     "node_modules/json-parse-even-better-errors": {
       "version": "2.3.1",
       "resolved": "https://registry.npmjs.org/json-parse-even-better-errors/-/json-parse-even-better-errors-2.3.1.tgz",

package.json

@@ -43,6 +43,7 @@
     ]
   },
   "dependencies": {
+    "json-colorizer": "^3.0.1",
     "uuid": "^9.0.1"
   }
 }

packages/backend/src/CoreModule.js

@@ -222,6 +222,9 @@ const install = async ({ services, app }) => {
 
     const { DetailProviderService } = require('./services/DetailProviderService');
     services.registerService('whoami', DetailProviderService);
+
+    const { DevTODService } = require('./services/DevTODService');
+    services.registerService('__dev-tod', DevTODService);
 }
 
 const install_legacy = async ({ services }) => {

packages/backend/src/Kernel.js

@@ -42,6 +42,7 @@ class Kernel extends AdvancedBase {
         // Temporary logger for boot process;
         // LoggerService will be initialized in app.js
         const bootLogger = new BootLogger();
+        this.bootLogger = bootLogger;
 
         // Determine config and runtime locations
         const runtimeEnv = new RuntimeEnvironment({
@@ -83,13 +84,14 @@ class Kernel extends AdvancedBase {
         // === START: Initialize Service Registry ===
         const { Container } = require('./services/Container');
 
-        const services = new Container();
+        const services = new Container({ logger: this.bootLogger });
         this.services = services;
         // app.set('services', services);
 
         const root_context = Context.create({
             services,
             config,
+            logger: this.bootLogger,
         }, 'app');
         globalThis.root_context = root_context;
 

packages/backend/src/filesystem/FSNodeContext.js

@@ -208,8 +208,7 @@ module.exports = class FSNodeContext {
             return;
         }
 
-        // NOTE: commented out for now because it's too verbose
-        this.log.info('fetching entry: ' + this.selector.describe(true));
+        this.log.info('fetching entry: ' + this.selector.describe());
         // All services at the top (DEVLOG-401)
         const {
             traceService,
@@ -239,9 +238,6 @@ module.exports = class FSNodeContext {
 
             const callback = (resolver) => {
                 // NOTE: commented out for now because it's too verbose
-                this.log.noticeme(`resolved by ${resolver}`, {
-                    debug: fetch_entry_options.debug,
-                });
                 resolved = true;
                 detachables.detach();
                 rslv();
@@ -273,13 +269,10 @@ module.exports = class FSNodeContext {
             }
         });
 
-        this.log.debug('got past the promise')
-
         if ( resourceService.getResourceInfo(this.uid) ) {
             entry = await fsEntryService.get(this.uid, fetch_entry_options);
             this.log.debug('got an entry from the future');
         } else {
-            this.log.debug('resource is already free');
             entry = await fsEntryFetcher.find(
                 this.selector, fetch_entry_options);
         }
@@ -734,7 +727,6 @@ module.exports = class FSNodeContext {
                     this.log.warn('null app');
                     continue;
                 }
-                this.log.debug('app?', { value:  app });
                 delete app.owner_user_id;
             }
         }

packages/backend/src/filesystem/storage/ResourceService.js

@@ -74,7 +74,7 @@ class ResourceService {
     }
 
     free (uid) {
-        this.log.info(`freeing`, uid);
+        this.log.info(`freeing`, { uid });
         const entry = this.uidToEntry[uid];
         if ( ! entry ) return;
         delete this.uidToEntry[uid];

packages/backend/src/om/entitystorage/ESBuilder.js

@@ -25,16 +25,13 @@ class ESBuilder {
             let last_was_cons = false;
             while ( ! last_was_cons ) {
                 const item = stack.pop();
-                console.log('item?', item)
                 if ( typeof item === 'function' ) {
-                    console.log('last was cons')
                     last_was_cons = true;
                 }
                 args.unshift(item);
             }
 
             const cls = args.shift();
-            console.log('cls?', cls)
             head = new cls({
                 ...(args[0] ?? {}),
                 ...(head ? { upstream: head } : {}),
@@ -55,7 +52,6 @@ class ESBuilder {
         // Print the classes in order
         let current = head;
         while ( current ) {
-            console.log(current.constructor.name);
             current = current.upstream;
         }
 

packages/backend/src/om/entitystorage/MaxLimitES.js

@@ -35,8 +35,6 @@ class MaxLimitES extends BaseES {
 
             options.limit = limit;
 
-            console.log('SELECT options (1)', options);
-
             return await this.upstream.select(options);
         }
     };

packages/backend/src/routers/filesystem_api/batch/all.js

@@ -141,17 +141,13 @@ module.exports = eggspress('/batch', {
             return;
         }
 
-        // log fileinfos
-        console.log('HERE ARE THE FILEINFOS');
-        console.log(JSON.stringify(fileinfos, null, 2));
-
         const indexes_to_remove = [];
 
         for ( let i=0 ; i < pending_operations.length ; i++ ) {
             const op_spec = pending_operations[i];
             if ( ! operation_requires_file(op_spec) ) {
                 indexes_to_remove.push(i);
-                console.log(`EXEUCING OP ${op_spec.op}`)
+                log.info(`executing ${op_spec.op}`);
                 response_promises.push(
                     batch_exe.exec_op(req, op_spec)
                 );
@@ -231,7 +227,6 @@ module.exports = eggspress('/batch', {
             batch_widget.ic = pending_operations.length;
             on_first_file();
         }
-        console.log(`GOT A FILE`)
 
         if ( fileinfos.length == 0 ) {
             request_errors_.push(
@@ -256,7 +251,6 @@ module.exports = eggspress('/batch', {
             stream.on('end', () => {
                 stream.destroy();
             });
-            console.log('DISCARDED A FILE');
             return;
         }
 
@@ -269,7 +263,7 @@ module.exports = eggspress('/batch', {
     });
 
     busboy.on('close', () => {
-        console.log('GOT DONE READING');
+        log.info('busboy close');
         still_reading.resolve();
     });
 
@@ -284,11 +278,11 @@ module.exports = eggspress('/batch', {
         return;
     }
 
-    log.noticeme('WAITING ON OPERATIONS')
+    log.info('waiting for operations')
     let responsePromises = response_promises;
     // let responsePromises = batch_exe.responsePromises;
     const results = await Promise.all(responsePromises);
-    log.noticeme('RESPONSE GETS SENT!');
+    log.info('sending response');
 
     frame.done();
 

packages/backend/src/routers/whoami.js

@@ -41,8 +41,6 @@ const WHOAMI_GET = eggspress('/whoami', {
 
     const is_user = actor.type instanceof UserActorType;
 
-    console.log('user?', req.user);
-
     // send user object
     const details = {
         username: req.user.username,

packages/backend/src/services/AppInformationService.js

@@ -170,14 +170,6 @@ class AppInformationService {
                 [origin + '%']
             ))[0];
 
-            if ( app.uid === 'app-eeec9a28-0eb1-5b63-a2dd-b99a8a3cf4c3' ) {
-                console.log('app?', app);
-                console.log('REFERRAL COUNT', referral_count, {
-                    sql,
-                    index_url: app.index_url,
-                });
-            }
-
             kv.set(key_referral_count, referral_count);
         }
 

packages/backend/src/services/Container.js

@@ -17,12 +17,14 @@
  * along with this program.  If not, see <https://www.gnu.org/licenses/>.
  */
 const config = require("../config");
+const { Context } = require("../util/context");
 const { CompositeError } = require("../util/errorutil");
 const { TeePromise } = require("../util/promise");
 
 // 17 lines of code instead of an entire dependency-injection framework
 class Container {
-    constructor () {
+    constructor ({ logger }) {
+        this.logger = logger;
         this.instances_ = {};
         this.ready = new TeePromise();
     }
@@ -83,12 +85,12 @@ class Container {
 
     async init () {
         for ( const k in this.instances_ ) {
-            console.log(`constructing ${k}`);
+            this.logger.info(`constructing ${k}`);
             await this.instances_[k].construct();
         }
         const init_failures = [];
         for ( const k in this.instances_ ) {
-            console.log(`initializing ${k}`);
+            this.logger.info(`initializing ${k}`);
             try {
                 await this.instances_[k].init();
             } catch (e) {

packages/backend/src/services/DevConsoleService.js

@@ -57,6 +57,7 @@ class DevConsoleService extends BaseService {
         // if a widget throws an error we MUST remove it;
         // it's probably a stack overflow because it's printing.
         const to_remove = [];
+        let positions = [];
         for ( const w of this.widgets ) {
             let output; try {
                 output = w();
@@ -66,8 +67,43 @@ class DevConsoleService extends BaseService {
                 continue;
             }
             output = Array.isArray(output) ? output : [output];
+            positions.push([this.static_lines.length, output.length]);
             this.static_lines.push(...output);
         }
+
+        const DESIRED_MIN_OUT = 10;
+        const size_ok = () =>
+            process.stdout.rows - DESIRED_MIN_OUT > this.static_lines.length;
+        let n_hidden = 0;
+        for ( let i = this.widgets.length-1 ; i >= 0 ; i-- ) {
+            if ( size_ok() ) break;
+            const w = this.widgets[i];
+            if ( ! w.unimportant ) continue;
+            n_hidden++;
+            const [start, length] = positions[i];
+            this.static_lines.splice(start, length);
+            // update positions
+            for ( let j = i ; j < positions.length ; j++ ) {
+                positions[j][0] -= length;
+            }
+        }
+        for ( let i = this.widgets.length-1 ; i >= 0 ; i-- ) {
+            if ( size_ok() ) break;
+            n_hidden++;
+            const w = this.widgets[i];
+            const [start, length] = positions[i];
+            this.static_lines.splice(start, length);
+        }
+        if ( n_hidden && size_ok() ) {
+            this.static_lines.push(
+                `\x1B[33m` +
+                this.generateEnd(
+                    `[ ${n_hidden} widget${n_hidden === 1 ? '' : 's'} hidden ]`
+                ) +
+                `\x1B[0m`
+            );
+        }
+
         if (!this.arrays_equal(initialOutput, this.static_lines)) {
             this.mark_updated();  // Update only if outputs have changed
         }

packages/backend/src/services/DevTODService.js

@@ -0,0 +1,86 @@
+const { surrounding_box } = require("../fun/dev-console-ui-utils");
+const BaseService = require("./BaseService");
+
+const SOURCE_CODE_TIPS = `
+    Most services are registered in CoreModule.js
+    Boot sequence events are different from service events
+    ExpectationService exists to ensure Puter doesn't miss a step
+    Services are composable; StrategyService is a good example
+    API endpoints should be on a separate origin in production
+    There is some limited query-building in packages/backend/src/om
+`;
+
+const tips = (
+    // CLI tips
+    `
+    Type \`help\` to see a list of commands
+    \`logs:show\` toggles log output; useful when typing long commands
+    \`logs:indent \` toggles indentation for some logs
+    \`lock:locks \` will list any active mutex locks
+    `,
+    // Source code tips
+    `
+    Most services are registered in CoreModule.js
+    Boot sequence events are different from service events
+    ExpectationService exists to ensure Puter doesn't miss a step
+    Services are composable; StrategyService is a good example
+    API endpoints should be on a separate origin in production
+    These messages come from DevTODService.js
+    `
+).split('\n').map((line) => line.trim())
+    .filter((line) => line.length)
+    .map(tip => {
+        const lines = [];
+        const WRAP = process.stdout.columns || 50;
+        while ( tip.length ) {
+            lines.push(tip.substring(0, WRAP));
+            tip = tip.substring(WRAP);
+        }
+        return lines;
+    })
+
+class DevTODService extends BaseService {
+    async _init () {
+        const svc_commands = this.services.get('commands');
+        this._register_commands(svc_commands);
+    }
+    async ['__on_boot.consolidation'] () {
+        const random_tip = tips[Math.floor(Math.random() * tips.length)];
+        this.tod_widget = () => {
+            const lines = [
+                "",
+                "\x1B[1mTip of the Day\x1B[0m",
+                ...random_tip,
+                "Type tod:dismiss to un-stick this message",
+                "",
+            ];
+            surrounding_box('33;1', lines);
+            return lines;
+        }
+
+        this.tod_widget.unimportant = true;
+
+        const svc_devConsole = this.services.get('dev-console', { optional: true });
+        if ( ! svc_devConsole ) return;
+        svc_devConsole.add_widget(this.tod_widget);
+    }
+
+    _register_commands (commands) {
+        commands.registerCommands('tod', [
+            {
+                id: 'dismiss',
+                description: 'Dismiss the startup message',
+                handler: async (_, log) => {
+                    const svc_devConsole = this.services.get('dev-console', { optional: true });
+                    if ( ! svc_devConsole ) return;
+                    svc_devConsole.remove_widget(this.tod_widget);
+                    const lines = this.tod_widget();
+                    for ( const line of lines ) log.log(line);
+                    this.tod_widget = null;
+                }
+            }
+        ]);
+    }
+}
+
+module.exports = { DevTODService };

packages/backend/src/services/DevWatcherService.js

@@ -54,12 +54,18 @@ class DevWatcherService extends BaseService {
     // but hey at least we have this convenient event listener.
     async ['__on_ready.webserver'] () {
         const { root, commands } = this.args;
+        let promises = [];
         for ( const entry of commands ) {
             const { directory } = entry;
             const fullpath = this.modules.path.join(
                 root, directory);
-            this.start_({ ...entry, fullpath });
+            promises.push(this.start_({ ...entry, fullpath }));
         }
+        await Promise.all(promises);
+
+        // It's difficult to tell when webpack is "done" its first
+        // run so we just wait a bit before we say we're ready.
+        await new Promise((resolve) => setTimeout(resolve, 3000));
     }
 
     log_ (name, isErr, line) {

packages/backend/src/services/EmailService.js

@@ -161,7 +161,6 @@ class Emailservice extends BaseService {
     }
 
     _init () {
-        console.log('the config', this.config);
     }
 
     get_transport_ () {

packages/backend/src/services/WebServerService.js

@@ -57,6 +57,7 @@ class WebServerService extends BaseService {
         const services = this.services;
         await services.emit('start.webserver');
         await services.emit('ready.webserver');
+        this.print_puter_logo_();
     }
 
     async ['__on_start.webserver'] () {
@@ -132,7 +133,7 @@ class WebServerService extends BaseService {
             const lines = [
                 "",
                 `Puter is now live at: ${link}`,
-                `Type web:dismiss to dismiss this message`,
+                `Type web:dismiss to un-stick this message`,
                 "",
             ];
             const lengths = [
@@ -149,8 +150,6 @@ class WebServerService extends BaseService {
             if ( svc_devConsole ) svc_devConsole.add_widget(this.startup_widget);
         }
 
-        this.print_puter_logo_();
-
         server.timeout = 1000 * 60 * 60 * 2; // 2 hours
         server.requestTimeout = 1000 * 60 * 60 * 2; // 2 hours
         server.headersTimeout = 1000 * 60 * 60 * 2; // 2 hours

packages/backend/src/services/auth/ACLService.js

@@ -100,8 +100,8 @@ class ACLService extends BaseService {
                     `fs:${await perm_fsNode.get('uid')}:${mode}`
                 );
                 if ( perm ) {
-                    console.log('TRUE BECAUSE PERMISSION', perm)
-                    console.log(`fs:${await perm_fsNode.get('uid')}:${mode}`)
+                    // console.log('TRUE BECAUSE PERMISSION', perm)
+                    // console.log(`fs:${await perm_fsNode.get('uid')}:${mode}`)
                     return true;
                 }
             }

packages/backend/src/services/drivers/implementations/BaseImplementation.js

@@ -109,8 +109,6 @@ class BaseImplementation extends AdvancedBase {
                 sla_key
             );
 
-            console.log('SLA KEY', sla_key, 'USER KEY', user_is_verified ? 'user_verified' : 'user_unverified');
-
             const user_method_key = `actor:${actor.uid}:${method_key}`;
 
             // short-term rate limiting

packages/backend/src/services/runtime-analysis/LogService.js

@@ -119,28 +119,40 @@ class LogContext {
 }
 
 let log_epoch = Date.now();
-const stringify_log_entry = ({ log_lvl, crumbs, message, fields, objects }) => {
-    let m = `\x1B[${log_lvl.esc}m[${log_lvl.label}\x1B[0m`;
+const stringify_log_entry = ({ prefix, log_lvl, crumbs, message, fields, objects }) => {
+    const { colorize } = require('json-colorizer');
+
+    let lines = [], m;
+    const lf = () => {
+        if ( ! m ) return;
+        lines.push(m);
+        m = '';
+    }
+
+    m = prefix ? `${prefix} ` : '';
+    m += `\x1B[${log_lvl.esc}m[${log_lvl.label}\x1B[0m`;
     for ( const crumb of crumbs ) {
         m += `::${crumb}`;
     }
     m += `\x1B[${log_lvl.esc}m]\x1B[0m`;
-    for ( const k in fields ) {
-        if ( k === 'timestamp' ) continue;
-        let v; try {
-            v = JSON.stringify(fields[k]);
-        } catch (e) {
-            v = '' + fields[k];
-        }
-        m += ` ${k}=${v}`;
-    }
     if ( fields.timestamp ) {
         // display seconds since logger epoch
         const n = (fields.timestamp - log_epoch) / 1000;
         m += ` (${n.toFixed(3)}s)`;
     }
     m += ` ${message} `;
-    return m;
+    lf();
+    for ( const k in fields ) {
+        if ( k === 'timestamp' ) continue;
+        let v; try {
+            v = colorize(JSON.stringify(fields[k]));
+        } catch (e) {
+            v = '' + fields[k];
+        }
+        m += ` \x1B[1m${k}:\x1B[0m ${v}`;
+        lf();
+    }
+    return lines.join('\n');
 };
 
 
@@ -148,6 +160,7 @@ class DevLogger {
     // TODO: this should eventually delegate to winston logger
     constructor (log, opt_delegate) {
         this.log = log;
+        this.off = false;
 
         if ( opt_delegate ) {
             this.delegate = opt_delegate;
@@ -159,11 +172,15 @@ class DevLogger {
                 log_lvl, crumbs, message, fields, objects,
             );
         }
+
+        if ( this.off ) return;
+
         const ld = Context.get('logdent', { allow_fallback: true })
         const prefix = globalThis.dev_console_indent_on
             ? Array(ld ?? 0).fill('    ').join('')
             : '';
-        this.log(prefix + stringify_log_entry({
+        this.log(stringify_log_entry({
+            prefix,
             log_lvl, crumbs, message, fields, objects,
         }));
     }
@@ -264,6 +281,26 @@ class LogService extends BaseService {
     register_log_middleware (callback) {
         this.loggers[0] = new CustomLogger(this.loggers[0], callback);
     }
+    ['__on_boot.consolidation'] () {
+        const commands = this.services.get('commands');
+        commands.registerCommands('logs', [
+            {
+                id: 'show',
+                description: 'toggle log output',
+                handler: async (args, log) => {
+                    this.devlogger && (this.devlogger.off = ! this.devlogger.off);
+                }
+            },
+            {
+                id: 'indent',
+                description: 'toggle log indentation',
+                handler: async (args, log) => {
+                    globalThis.dev_console_indent_on =
+                        ! globalThis.dev_console_indent_on;
+                }
+            }
+        ]);
+    }
     async _init () {
         const config = this.global_config;
 
@@ -312,6 +349,8 @@ class LogService extends BaseService {
             logger = config.flag_no_logs // useful for profiling
                 ? new NullLogger()
                 : new DevLogger(console.log.bind(console), logger);
+            
+            this.devlogger = logger;
         }
 
         logger = new TimestampLogger(logger);
@@ -321,7 +360,7 @@ class LogService extends BaseService {
 
         this.loggers.push(logger);
 
-        this.output_lvl = LOG_LEVEL_DEBU;
+        this.output_lvl = LOG_LEVEL_INFO;
         if ( config.logger ) {
             // config.logger.level is a string, e.g. 'debug'
 
@@ -349,6 +388,7 @@ class LogService extends BaseService {
         });
 
         this.services.logger = this.create('services-container');
+        globalThis.root_context.set('logger', this.create('root-context'));
     }
 
     create (prefix, fields = {}) {

packages/backend/src/services/sla/MonthlyUsageService.js

@@ -43,7 +43,6 @@ class MonthlyUsageService extends BaseService {
                     year, month, key, actor.type.user.id, maybe_app_id, JSON.stringify(extra),
                     ...this.db.case({ mysql: [JSON.stringify(extra)], otherwise: [] }),
                 ]
-        console.log('VALS', vals);
 
         // UPSERT increment count
         try {