Merge pull request #55 from saskodh/FR#40_logging

Fr#40 logging

package.json

@@ -33,7 +33,8 @@
     "lodash": "^4.12.0",
     "reflect-metadata": "^0.1.3",
     "zone.js": "^0.6.15",
-    "object-hash": "^1.1.3"
+    "object-hash": "^1.1.3",
+    "winston": "^2.2.0"
   },
   "devDependencies": {
     "chai": "3.5.0",

src/index.ts

@@ -19,18 +19,18 @@ export {RequestMapping, RequestMappingConfig, RequestMethod} from "./lib/decorat
 export {Interceptor} from "./lib/decorators/InterceptorDecorator";
 export {Order} from "./lib/decorators/OrderDecorator";
 export {Aspect, Before, After, AfterReturning, AfterThrowing, Around} from "./lib/decorators/AspectDecorator";
+export {Cacheable, CacheEvict, CachePut} from "./lib/decorators/CacheableDecorator";
+export {EnableCaching} from "./lib/decorators/EnableCachingDecorator";
 
 export { RequestContext, REQUEST_TOKEN, RESPONSE_TOKEN } from "./lib/web/context/RequestContext";
 export { RequestContextHolder } from "./lib/web/context/RequestContextHolder";
 
-export {Cacheable, CacheEvict, CachePut} from "./lib/decorators/CacheableDecorator";
-export {EnableCaching} from "./lib/decorators/EnableCachingDecorator";
-
 export {ApplicationContext} from "./lib/di/ApplicationContext";
 export {ComponentDefinitionPostProcessor, IComponentDefinitionPostProcessor}
     from "./lib/processors/ComponentDefinitionPostProcessor";
 export {ComponentPostProcessor, IComponentPostProcessor} from "./lib/processors/ComponentPostProcessor";
 export {Environment} from "./lib/di/Environment";
+export { LoggerFactory } from "./lib/helpers/logging/LoggerFactory";
 
 // exported error definitions
 export {ApplicationContextError, ComponentInitializationError, ComponentWiringError,
@@ -41,4 +41,5 @@ export {DecoratorUsageError, DecoratorUsageTypeError} from "./lib/errors/Decorat
 export {InjectionError} from "./lib/errors/InjectionError"
 export {InvalidUsageError} from "./lib/errors/InvalidUsageError"
 export {WebError, RouteHandlerError, InterceptorError} from "./lib/errors/WebErrors"
-export {AspectError, AfterAdviceError, AfterReturningAdviceError, BeforeAdviceError} from "./lib/errors/AspectErrors"
+export {AspectError, AfterAdviceError, AfterReturningAdviceError, BeforeAdviceError,
+    AfterThrowingAdviceError} from "./lib/errors/AspectErrors"

src/lib/decorators/ComponentScanDecorator.ts

@@ -6,6 +6,9 @@ import { ComponentUtil } from "./ComponentDecorator";
 import { RequireUtils } from "../helpers/RequireUtils";
 import { Environment } from "../di/Environment";
 import { DecoratorType, DecoratorUtil } from "../helpers/DecoratorUtils";
+import { LoggerFactory } from "../helpers/logging/LoggerFactory";
+
+let logger = LoggerFactory.getInstance();
 
 /**
  *A decorator for setting up project files to be component-scanned.
@@ -48,7 +51,7 @@ export class ComponentScanUtil {
 
             // if it's JavaScript file load it
             if (lstat.isFile() && path_module.extname(fileName) === '.js') {
-                console.log(`Loading dynamically by @ComponentScan: ${fileName} (${filePath})`);
+                logger.debug(`Loading dynamically by @ComponentScan: ${fileName} (${filePath})`);
                 yield RequireUtils.require(filePath);
             }
 

src/lib/decorators/ConfigurationDecorator.ts

@@ -4,7 +4,9 @@ import { Component, ComponentUtil } from "./ComponentDecorator";
 import { Environment } from "../di/Environment";
 import { DecoratorUsageError, DecoratorUsageTypeError } from "../errors/DecoratorUsageErrors";
 import { DecoratorUtil, DecoratorType } from "../helpers/DecoratorUtils";
+import { LoggerFactory } from "../helpers/logging/LoggerFactory";
 
+let logger = LoggerFactory.getInstance();
 const CONFIGURATION_HOLDER_TOKEN = Symbol('configuration_holder_token');
 
 export class ProfiledPath {
@@ -39,6 +41,7 @@ export class ConfigurationData {
     }
 
     loadAllComponents(environment: Environment) {
+        logger.info('Loading components by component scan...');
         ComponentScanUtil.getComponentsFromPaths(this.componentScanPaths, environment)
             .forEach((component) => {
                 if (ComponentUtil.isComponentDefinitionPostProcessor(component)) {

src/lib/decorators/ImportDecorator.ts

@@ -1,6 +1,10 @@
 import { ConfigurationUtil } from "./ConfigurationDecorator";
 import { DecoratorBadArgumentError } from "../errors/BadArgumentErrors";
 import { DecoratorType, DecoratorUtil } from "../helpers/DecoratorUtils";
+import { ComponentUtil } from "./ComponentDecorator";
+import { LoggerFactory } from "../helpers/logging/LoggerFactory";
+
+let logger = LoggerFactory.getInstance();
 
 /**
  * Decorator used for composing configuration classes by importing other configuration classes.
@@ -18,6 +22,8 @@ export function Import(...configurationClasses) {
                 throw new DecoratorBadArgumentError(`${configurationClass.name} is not a configuration class.`,
                     Import, [...arguments]);
             }
+            logger.debug(`Importing configurations from ${ComponentUtil.getComponentData(configurationClass)
+                .componentName} to ${ComponentUtil.getComponentData(targetConfigurationClass).componentName}`);
             let configurationData = ConfigurationUtil.getConfigurationData(configurationClass);
             targetConfigurationData.componentFactory.components.push(...configurationData.componentFactory.components);
             targetConfigurationData.componentDefinitionPostProcessorFactory.components

src/lib/decorators/PropertySourceDecorator.ts

@@ -4,6 +4,9 @@ import { GeneralUtils } from "../helpers/GeneralUtils";
 import {RequireUtils} from "../helpers/RequireUtils";
 import { DecoratorType, DecoratorUtil } from "../helpers/DecoratorUtils";
 import { BadArgumentError } from "../errors/BadArgumentErrors";
+import { LoggerFactory } from "../helpers/logging/LoggerFactory";
+
+let logger = LoggerFactory.getInstance();
 
 /**
  * A decorator for defining a JSON property source for the configuration properties.
@@ -23,7 +26,7 @@ export class PropertySourceUtil {
     static getPropertiesFromPaths(...propertySourcePaths: Array<string>): Map<string, string> {
         let resultPropertiesMap = new Map<string, string>();
         for (let path of propertySourcePaths) {
-            console.log(`Loading properties by @PropertySource from "${path}"`);
+            logger.debug(`Loading properties by @PropertySource from "${path}"`);
             let properties;
             try {
                 properties = RequireUtils.require(path);

src/lib/di/ApplicationContext.ts

@@ -21,6 +21,9 @@ import {
 } from "../errors/ApplicationContextErrors";
 import {DynamicDependencyResolver} from "./DynamicDependencyResolver";
 import { CacheDefinitionPostProcessor } from "../processors/cache/CacheDefinitionPostProcessor";
+import { LoggerFactory } from "../helpers/logging/LoggerFactory";
+
+let logger = LoggerFactory.getInstance();
 
 export class ApplicationContextState {
     static NOT_INITIALIZED = 'NOT_INITIALIZED';
@@ -39,6 +42,7 @@ export class ApplicationContext {
 
     constructor(configurationClass) {
         this.state = ApplicationContextState.NOT_INITIALIZED;
+        logger.info('Constructing the application context...');
         this.injector = new Injector();
         this.dispatcher = new Dispatcher();
         this.configurationData = ConfigurationUtil.getConfigurationData(configurationClass);
@@ -78,9 +82,10 @@ export class ApplicationContext {
      * */
     async start() {
         if (this.state !== ApplicationContextState.NOT_INITIALIZED) {
-            console.warn("Application context was already initialized or it is initializing at the moment.");
+            logger.warn("Application context was already initialized or it is initializing at the moment.");
         }
         this.state = ApplicationContextState.INITIALIZING;
+        logger.info('Stating the application context...');
 
         await this.initializeDefinitionPostProcessors();
         await this.initializePostProcessors();
@@ -119,6 +124,7 @@ export class ApplicationContext {
      * Manually destroys the application context. Running @PreDestroy method on all components.
      */
     async destroy() {
+        logger.info('Destroying the application context...');
         if (this.state === ApplicationContextState.READY) {
             await this.executePreDestruction();
         }
@@ -139,8 +145,10 @@ export class ApplicationContext {
     }
 
     private initializeComponents() {
+        logger.info(`Initializing ApplicationContext's components...`);
         for (let CompConstructor of this.getActiveComponents()) {
             let componentData = ComponentUtil.getComponentData(CompConstructor);
+            logger.debug(`Initializing ${componentData.componentName} component.`);
 
             let instance;
             try {
@@ -156,11 +164,13 @@ export class ApplicationContext {
     }
 
     private wireComponents() {
+        logger.info(`Wiring ApplicationContext's components...`);
         for (let CompConstructor of this.getActiveComponents()) {
             let componentData = ComponentUtil.getComponentData(CompConstructor);
             let injectionData = ComponentUtil.getInjectionData(CompConstructor);
             let instance = this.injector.getComponent(componentData.classToken);
 
+            logger.debug(`Wiring dependencies for '${componentData.componentName}' component.`);
             injectionData.dependencies.forEach((dependencyData, fieldName) => {
                 let dependency;
                 try {
@@ -176,6 +186,8 @@ export class ApplicationContext {
                let dynamicResolver = new DynamicDependencyResolver(this.injector, dependencyData);
                 Object.defineProperty(instance, fieldName, dynamicResolver.getPropertyDescriptor());
             });
+
+            logger.debug(`Wiring properties for '${componentData.componentName}' component.`);
             injectionData.properties.forEach((propertyKey, fieldName) => {
                 Reflect.set(instance, fieldName, this.environment.getProperty(propertyKey));
             });
@@ -185,12 +197,15 @@ export class ApplicationContext {
     }
 
     private initializeDefinitionPostProcessors() {
+        logger.verbose('Initializing component definition post processors...');
         // NOTE: add custom defined component definition post processors
         this.configurationData.componentDefinitionPostProcessorFactory.components.push(AspectDefinitionPostProcessor);
 
         // NOTE: initialize all component definition post processors
         for (let CompConstructor of this.getActiveDefinitionPostProcessors()) {
             let componentData = ComponentUtil.getComponentData(CompConstructor);
+            logger.debug(`Initializing and registering component definition post processor: '${componentData
+                .componentName}'`);
 
             let instance = new CompConstructor();
             if (!ComponentDefinitionPostProcessorUtil.isIComponentDefinitionPostProcessor(instance)) {
@@ -208,8 +223,10 @@ export class ApplicationContext {
     }
 
     private initializePostProcessors() {
+        logger.verbose('Initializing component post processors...');
         for (let CompConstructor of this.getActivePostProcessors()) {
             let componentData = ComponentUtil.getComponentData(CompConstructor);
+            logger.debug(`Initializing and registering component post processor: '${componentData.componentName}'`);
 
             let instance = new CompConstructor();
             if (!ComponentPostProcessorUtil.isIComponentPostProcessor(instance)) {
@@ -225,22 +242,25 @@ export class ApplicationContext {
     }
 
     private async postProcessDefinition() {
+        logger.info('Postprocessing component definitions...');
         this.configurationData.componentFactory.components = _.map(
             this.configurationData.componentFactory.components, (componentDefinition) => {
+                logger.debug(`Postprocessing component definition for: '${componentDefinition.name}'`);
                 for (let componentDefinitionPostProcessor of this.getOrderedDefinitionPostProcessors()) {
                     let result;
                     try {
                         result = componentDefinitionPostProcessor.postProcessDefinition(componentDefinition);
                     } catch (err) {
                         throw new PostProcessError(`postProcessDefinition() from ${componentDefinitionPostProcessor.
-                                constructor.name} failed on ${componentDefinition.constructor.name}`, err);
+                            constructor.name} failed on ${ComponentUtil
+                            .getComponentData(componentDefinition).componentName}`, err);
                     }
                     if (_.isFunction(result)) {
                         componentDefinition = result;
                     } else if (!_.isUndefined(result)) {
                         throw new PostProcessError(componentDefinitionPostProcessor.constructor.name +
                             ' (Component Definition Post Processor) must return a constructor function for component ' +
-                            componentDefinition.constructor.name);
+                            ComponentUtil.getComponentData(componentDefinition).componentName);
                     }
                 }
                 return componentDefinition;
@@ -249,10 +269,13 @@ export class ApplicationContext {
     }
 
     private async postProcessBeforeInit() {
+        logger.info('Postprocessing components before initialization...');
         for (let componentPostProcessor of this.getOrderedPostProcessors()) {
 
             for (let componentConstructor of this.getActiveComponents()) {
                 let componentData = ComponentUtil.getComponentData(componentConstructor);
+                logger.debug(`Post processing component '${componentData.componentName}' by 
+                    '${componentPostProcessor.name}' component post processor.`);
                 let instance = this.injector.getComponent(componentData.classToken);
                 try {
                     componentPostProcessor.postProcessBeforeInit(instance);
@@ -265,10 +288,13 @@ export class ApplicationContext {
     }
 
     private async postProcessAfterInit() {
+        logger.info('Postprocessing components after initialization...');
         for (let componentPostProcessor of this.getOrderedPostProcessors()) {
 
             for (let componentConstructor of this.getActiveComponents()) {
                 let componentData = ComponentUtil.getComponentData(componentConstructor);
+                logger.debug(`Post processing component '${componentData.componentName}' by 
+                    '${componentPostProcessor.name}' component post processor.`);
                 let instance = this.injector.getComponent(componentData.classToken);
                 try {
                     componentPostProcessor.postProcessAfterInit(instance);
@@ -281,6 +307,7 @@ export class ApplicationContext {
     }
 
     private async executePostConstruction() {
+        logger.info('Executing @PostConstruct methods for all components...');
         for (let CompConstructor of this.getActiveComponents()) {
             let componentData = ComponentUtil.getComponentData(CompConstructor);
             let postConstructMethod = LifeCycleHooksUtil.getConfig(CompConstructor).postConstructMethod;
@@ -289,6 +316,7 @@ export class ApplicationContext {
                 if (!_.isFunction(instance[postConstructMethod])) {
                     throw new DecoratorUsageError(`@PostConstruct is not on a method (${postConstructMethod})`);
                 }
+                logger.debug(`Executing @PostConstruct method for '${componentData.componentName}' component.`);
                 try {
                     await instance[postConstructMethod]();
                 } catch (err) {
@@ -299,6 +327,7 @@ export class ApplicationContext {
     }
 
     private async executePreDestruction() {
+        logger.info('Executing @PreDestroy methods for all components...');
         for (let CompConstructor of this.getActiveComponents()) {
             let componentData = ComponentUtil.getComponentData(CompConstructor);
             let preDestroyMethod = LifeCycleHooksUtil.getConfig(CompConstructor).preDestroyMethod;
@@ -307,6 +336,7 @@ export class ApplicationContext {
                 if (!_.isFunction(instance[preDestroyMethod])) {
                     throw new DecoratorUsageError(`@PreDestroy is not on a method (${preDestroyMethod})`);
                 }
+                logger.debug(`Executing @PreDestroy method for '${componentData.componentName}' component.`);
                 try {
                     await instance[preDestroyMethod]();
                 } catch (err) {
@@ -390,6 +420,7 @@ export class ApplicationContext {
     }
 
     private initializeEnvironment() {
+        logger.info(`Initializing the ApplicationContext's Environment...`);
         this.environment = new Environment();
         this.environment.setActiveProfiles(...this.configurationData.activeProfiles);
         this.environment.setApplicationProperties(this.configurationData.propertySourcePaths);

src/lib/di/Environment.ts

@@ -4,6 +4,9 @@ import { Component } from "../decorators/ComponentDecorator";
 import { PropertySourceUtil } from "../decorators/PropertySourceDecorator";
 import { ProfiledPath } from "../decorators/ConfigurationDecorator";
 import { BadArgumentError } from "../errors/BadArgumentErrors";
+import { LoggerFactory } from "../helpers/logging/LoggerFactory";
+
+let logger = LoggerFactory.getInstance();
 
 @Component()
 export class Environment {
@@ -85,6 +88,7 @@ export class Environment {
     }
 
     setApplicationProperties(propertySourcePaths: Array<ProfiledPath>) {
+        logger.verbose('Importing application properties.');
         let isActiveProfilesPropertySet = (!_.isUndefined(this.getProperty(this.ACTIVE_PROFILES_PROPERTY_KEY)));
         let viablePaths = _.map(_.filter(propertySourcePaths, (profiledPath: ProfiledPath) =>
                 (profiledPath.profiles.length === 0 || this.acceptsProfiles(...profiledPath.profiles))),

src/lib/errors/AspectErrors.ts

@@ -28,4 +28,6 @@ export class BeforeAdviceError extends AspectError {}
 
 export class AfterAdviceError extends AspectError {}
 
-export class AfterReturningAdviceError extends AspectError {}
+export class AfterReturningAdviceError extends AspectError {}
+
+export class AfterThrowingAdviceError extends AspectError {}

src/lib/helpers/logging/LoggerFactory.ts

@@ -0,0 +1,49 @@
+import { loggers, transports, LoggerInstance, LoggerOptions, LogCallback } from "winston";
+
+export interface LoggerMethod {
+    (msg: string, callback: LogCallback): Logger;
+    (msg: string, meta: any, callback: LogCallback): Logger;
+    (msg: string, ... meta: any[]): Logger;
+}
+
+export interface Logger {
+    debug: LoggerMethod;
+    verbose: LoggerMethod;
+    info: LoggerMethod;
+    warn: LoggerMethod;
+    error: LoggerMethod;
+}
+
+// FIXME winston issue [#814]: log statements are not in the correct order
+export class LoggerFactory {
+
+    public static FRAMEWORK_LOGGER_NAME = 'framework-logger';
+    private static logger: LoggerInstance;
+
+    static getInstance(): Logger {
+        if (!this.logger) {
+            this.logger = this.createFrameworkLogger();
+        }
+        return <any> this.logger;
+    }
+
+    private static createFrameworkLogger(): LoggerInstance {
+        return loggers.add(this.FRAMEWORK_LOGGER_NAME, this.getFrameworkLoggerOptions());
+    }
+
+    private static getFrameworkLoggerOptions(): LoggerOptions {
+        return {
+            transports: [
+                new transports.Console({
+                    handleExceptions: false,
+                    level: process.env.LOG_LEVEL || 'debug',
+                    timestamp: function () { return new Date().toISOString(); },
+                    formatter: function (options) {
+                        return `${options.timestamp()}  | ${options.level.toUpperCase()}\t| ${options.message}`;
+                    }
+                })
+            ]
+        };
+    }
+}
+