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

feat(backend): improve logger and reduce logs
HeyPuter · Jun 1, 2024 · 135b5ec · 135b5ec
2 parents 522664d + 2d8e624
commit 135b5ec
Show file tree

Hide file tree

Showing 21 changed files with 219 additions and 64 deletions.
diff --git a/package-lock.json b/package-lock.json
diff --git a/package.json b/package.json
@@ -43,6 +43,7 @@
     ]
   },
   "dependencies": {
+    "json-colorizer": "^3.0.1",
     "uuid": "^9.0.1"
   }
 }
diff --git a/packages/backend/src/CoreModule.js b/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 }) => {

diff --git a/packages/backend/src/Kernel.js b/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;
 

diff --git a/packages/backend/src/filesystem/FSNodeContext.js b/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;
             }
         }

diff --git a/packages/backend/src/filesystem/storage/ResourceService.js b/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];

diff --git a/packages/backend/src/om/entitystorage/ESBuilder.js b/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;
         }
 

diff --git a/packages/backend/src/om/entitystorage/MaxLimitES.js b/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);
         }
     };

diff --git a/packages/backend/src/routers/filesystem_api/batch/all.js b/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();
 

diff --git a/packages/backend/src/routers/whoami.js b/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,

diff --git a/packages/backend/src/services/AppInformationService.js b/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);
         }
 

diff --git a/packages/backend/src/services/Container.js b/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) {

diff --git a/packages/backend/src/services/DevConsoleService.js b/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
         }