feat(boot): add debug logs for better troubleshooting

Make it easier to troubleshoot the situation when a booter is not
recognizing artifact files and/or classes exported by those files.

To make debug logs easy to read, absolute paths are converted to
project-relative paths in debug logs. This change required a refactoring
of Booter design, where "projectRoot" becomes a required constructor
argument.

While making these changes, I changed "options" to be a required
constructor argument too, and chaged both "options" and "projectRoot"
to readonly properties.

Author: bajtos

packages/boot/src/booters/base-artifact.booter.ts

@@ -4,8 +4,12 @@
 // License text available at https://opensource.org/licenses/MIT
 
 import {Constructor} from '@loopback/context';
+import * as debugFactory from 'debug';
+import * as path from 'path';
+import {ArtifactOptions, Booter} from '../interfaces';
 import {discoverFiles, loadClassesFromFiles} from './booter-utils';
-import {Booter, ArtifactOptions} from '../interfaces';
+
+const debug = debugFactory('loopback:boot:base-artifact-booter');
 
 /**
  * This class serves as a base class for Booters which follow a pattern of
@@ -35,14 +39,27 @@ export class BaseArtifactBooter implements Booter {
   /**
    * Options being used by the Booter.
    */
-  options: ArtifactOptions;
-  projectRoot: string;
+  readonly options: ArtifactOptions;
+  readonly projectRoot: string;
   dirs: string[];
   extensions: string[];
   glob: string;
   discovered: string[];
   classes: Array<Constructor<{}>>;
 
+  constructor(projectRoot: string, options: ArtifactOptions) {
+    this.projectRoot = projectRoot;
+    this.options = options;
+  }
+
+  /**
+   * Get the name of the artifact loaded by this booter, e.g. "Controller".
+   * Subclasses can override the default logic based on the class name.
+   */
+  get artifactName(): string {
+    return this.constructor.name.replace(/Booter$/, '');
+  }
+
   /**
    * Configure the Booter by initializing the 'dirs', 'extensions' and 'glob'
    * properties.
@@ -78,7 +95,25 @@ export class BaseArtifactBooter implements Booter {
    * 'discovered' property.
    */
   async discover() {
+    debug(
+      'Discovering %s artifacts in %j using glob %j',
+      this.artifactName,
+      this.projectRoot,
+      this.glob,
+    );
+
     this.discovered = await discoverFiles(this.glob, this.projectRoot);
+
+    if (debug.enabled) {
+      debug(
+        'Artifact files found: %s',
+        JSON.stringify(
+          this.discovered.map(f => path.relative(this.projectRoot, f)),
+          null,
+          2,
+        ),
+      );
+    }
   }
 
   /**
@@ -90,6 +125,6 @@ export class BaseArtifactBooter implements Booter {
    * and then process the artifact classes as appropriate.
    */
   async load() {
-    this.classes = loadClassesFromFiles(this.discovered);
+    this.classes = loadClassesFromFiles(this.discovered, this.projectRoot);
   }
 }

packages/boot/src/booters/booter-utils.ts

@@ -4,9 +4,13 @@
 // License text available at https://opensource.org/licenses/MIT
 
 import {Constructor} from '@loopback/context';
+import * as debugFactory from 'debug';
+import * as path from 'path';
 import {promisify} from 'util';
 const glob = promisify(require('glob'));
 
+const debug = debugFactory('loopback:boot:booter-utils');
+
 /**
  * Returns all files matching the given glob pattern relative to root
  *
@@ -42,16 +46,23 @@ export function isClass(target: any): target is Constructor<any> {
  * @param files An array of string of absolute file paths
  * @returns {Constructor<{}>[]} An array of Class constructors from a file
  */
-export function loadClassesFromFiles(files: string[]): Constructor<{}>[] {
+export function loadClassesFromFiles(
+  files: string[],
+  projectRootDir: string,
+): Constructor<{}>[] {
   const classes: Array<Constructor<{}>> = [];
   for (const file of files) {
+    debug('Loading artifact file %j', path.relative(projectRootDir, file));
     const moduleObj = require(file);
     // WORKAROUND: use `for in` instead of Object.values().
     // See https://github.com/nodejs/node/issues/20278
     for (const k in moduleObj) {
       const exported = moduleObj[k];
       if (isClass(exported)) {
+        debug('  add %s (class %s)', k, exported.name);
         classes.push(exported);
+      } else {
+        debug('  skip non-class %s', k);
       }
     }
   }

packages/boot/src/booters/controller.booter.ts

@@ -22,13 +22,15 @@ import {BootBindings} from '../keys';
 export class ControllerBooter extends BaseArtifactBooter {
   constructor(
     @inject(CoreBindings.APPLICATION_INSTANCE) public app: Application,
-    @inject(BootBindings.PROJECT_ROOT) public projectRoot: string,
+    @inject(BootBindings.PROJECT_ROOT) projectRoot: string,
     @inject(`${BootBindings.BOOT_OPTIONS}#controllers`)
     public controllerConfig: ArtifactOptions = {},
   ) {
-    super();
-    // Set Controller Booter Options if passed in via bootConfig
-    this.options = Object.assign({}, ControllerDefaults, controllerConfig);
+    super(
+      projectRoot,
+      // Set Controller Booter Options if passed in via bootConfig
+      Object.assign({}, ControllerDefaults, controllerConfig),
+    );
   }
 
   /**

packages/boot/src/booters/datasource.booter.ts

@@ -28,13 +28,15 @@ export class DataSourceBooter extends BaseArtifactBooter {
   constructor(
     @inject(CoreBindings.APPLICATION_INSTANCE)
     public app: ApplicationWithRepositories,
-    @inject(BootBindings.PROJECT_ROOT) public projectRoot: string,
+    @inject(BootBindings.PROJECT_ROOT) projectRoot: string,
     @inject(`${BootBindings.BOOT_OPTIONS}#datasources`)
     public datasourceConfig: ArtifactOptions = {},
   ) {
-    super();
-    // Set DataSource Booter Options if passed in via bootConfig
-    this.options = Object.assign({}, DataSourceDefaults, datasourceConfig);
+    super(
+      projectRoot,
+      // Set DataSource Booter Options if passed in via bootConfig
+      Object.assign({}, DataSourceDefaults, datasourceConfig),
+    );
   }
 
   /**

packages/boot/src/booters/repository.booter.ts

@@ -25,13 +25,15 @@ export class RepositoryBooter extends BaseArtifactBooter {
   constructor(
     @inject(CoreBindings.APPLICATION_INSTANCE)
     public app: ApplicationWithRepositories,
-    @inject(BootBindings.PROJECT_ROOT) public projectRoot: string,
+    @inject(BootBindings.PROJECT_ROOT) projectRoot: string,
     @inject(`${BootBindings.BOOT_OPTIONS}#repositories`)
     public repositoryOptions: ArtifactOptions = {},
   ) {
-    super();
-    // Set Repository Booter Options if passed in via bootConfig
-    this.options = Object.assign({}, RepositoryDefaults, repositoryOptions);
+    super(
+      projectRoot,
+      // Set Repository Booter Options if passed in via bootConfig
+      Object.assign({}, RepositoryDefaults, repositoryOptions),
+    );
   }
 
   /**

packages/boot/test/unit/booters/base-artifact.booter.unit.ts

@@ -6,51 +6,56 @@
 import {BaseArtifactBooter} from '../../../index';
 import {expect} from '@loopback/testlab';
 import {resolve} from 'path';
+import {ArtifactOptions} from '../../../src';
 
 describe('base-artifact booter unit tests', () => {
-  let booterInst: BaseArtifactBooter;
-
-  beforeEach(getBaseBooter);
+  const TEST_OPTIONS = {
+    dirs: ['test', 'test2'],
+    extensions: ['.test.js', 'test2.js'],
+    nested: false,
+  };
 
   describe('configure()', () => {
-    const options = {
-      dirs: ['test', 'test2'],
-      extensions: ['.test.js', 'test2.js'],
-      nested: false,
-    };
-
     it(`sets 'dirs' / 'extensions' properties as an array if a string`, async () => {
-      booterInst.options = {dirs: 'test', extensions: '.test.js', nested: true};
+      const booterInst = givenBaseBooter({
+        dirs: 'test',
+        extensions: '.test.js',
+        nested: true,
+      });
       await booterInst.configure();
       expect(booterInst.dirs).to.be.eql(['test']);
       expect(booterInst.extensions).to.be.eql(['.test.js']);
     });
 
     it(`creates and sets 'glob' pattern`, async () => {
-      booterInst.options = options;
+      const booterInst = givenBaseBooter();
       const expected = '/@(test|test2)/*@(.test.js|test2.js)';
       await booterInst.configure();
       expect(booterInst.glob).to.equal(expected);
     });
 
     it(`creates and sets 'glob' pattern (nested)`, async () => {
-      booterInst.options = Object.assign({}, options, {nested: true});
+      const booterInst = givenBaseBooter(
+        Object.assign({}, TEST_OPTIONS, {nested: true}),
+      );
       const expected = '/@(test|test2)/**/*@(.test.js|test2.js)';
       await booterInst.configure();
       expect(booterInst.glob).to.equal(expected);
     });
 
     it(`sets 'glob' pattern to options.glob if present`, async () => {
       const expected = '/**/*.glob';
-      booterInst.options = Object.assign({}, options, {glob: expected});
+      const booterInst = givenBaseBooter(
+        Object.assign({}, TEST_OPTIONS, {glob: expected}),
+      );
       await booterInst.configure();
       expect(booterInst.glob).to.equal(expected);
     });
   });
 
   describe('discover()', () => {
     it(`sets 'discovered' property`, async () => {
-      booterInst.projectRoot = __dirname;
+      const booterInst = givenBaseBooter();
       // Fake glob pattern so we get an empty array
       booterInst.glob = '/abc.xyz';
       await booterInst.discover();
@@ -60,6 +65,7 @@ describe('base-artifact booter unit tests', () => {
 
   describe('load()', () => {
     it(`sets 'classes' property to Classes from a file`, async () => {
+      const booterInst = givenBaseBooter();
       booterInst.discovered = [
         resolve(__dirname, '../../fixtures/multiple.artifact.js'),
       ];
@@ -69,7 +75,7 @@ describe('base-artifact booter unit tests', () => {
     });
   });
 
-  async function getBaseBooter() {
-    booterInst = new BaseArtifactBooter();
+  function givenBaseBooter(options?: ArtifactOptions) {
+    return new BaseArtifactBooter(__dirname, options || TEST_OPTIONS);
   }
 });

packages/boot/test/unit/booters/booter-utils.unit.ts

@@ -67,7 +67,7 @@ describe('booter-utils unit tests', () => {
       const files = [resolve(SANDBOX_PATH, 'multiple.artifact.js')];
       const NUM_CLASSES = 2; // Number of classes in above file
 
-      const classes = loadClassesFromFiles(files);
+      const classes = loadClassesFromFiles(files, sandbox.path);
       expect(classes).to.have.lengthOf(NUM_CLASSES);
       expect(classes[0]).to.be.a.Function();
       expect(classes[1]).to.be.a.Function();
@@ -79,14 +79,16 @@ describe('booter-utils unit tests', () => {
       );
       const files = [resolve(SANDBOX_PATH, 'empty.artifact.js')];
 
-      const classes = loadClassesFromFiles(files);
+      const classes = loadClassesFromFiles(files, sandbox.path);
       expect(classes).to.be.an.Array();
       expect(classes).to.be.empty();
     });
 
     it('throws an error given a non-existent file', async () => {
       const files = [resolve(SANDBOX_PATH, 'fake.artifact.js')];
-      expect(() => loadClassesFromFiles(files)).to.throw(/Cannot find module/);
+      expect(() => loadClassesFromFiles(files, sandbox.path)).to.throw(
+        /Cannot find module/,
+      );
     });
   });
 });