feat(backend): improve logger and reduce logs

Author: KernelDeimos

package-lock.json

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

package.json

@@ -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/Kernel.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/FSNodeContext.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/filesystem/storage/ResourceService.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/ESBuilder.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/om/entitystorage/MaxLimitES.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/filesystem_api/batch/all.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/routers/whoami.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/AppInformationService.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/Container.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/DevWatcherService.js

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

packages/backend/src/services/EmailService.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/WebServerService.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/auth/ACLService.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