feat(rum-core): improve the debug logs with transaction details (#469)

* feat(rum-core): improve the debug logs with transaction details * change log format based on review * lower case all logs and fix tests
elastic · Nov 13, 2019 · b9629b4 · b9629b4
1 parent 0ea747e
commit b9629b4
Show file tree

Hide file tree

Showing 9 changed files with 74 additions and 58 deletions.
diff --git a/packages/rum-core/src/common/logging-service.js b/packages/rum-core/src/common/logging-service.js
@@ -26,8 +26,7 @@
 import { noop } from './utils'
 
 class LoggingService {
-  constructor(spec) {
-    if (!spec) spec = {}
+  constructor(spec = {}) {
     this.levels = ['trace', 'debug', 'info', 'warn', 'error']
     this.level = spec.level || 'info'
     this.prefix = spec.prefix || ''
@@ -65,13 +64,10 @@ class LoggingService {
         }
         var args = arguments
         if (prefix) {
-          if (typeof prefix === 'function') prefix = prefix(level)
           args[0] = prefix + args[0]
         }
         if (console) {
-          var realMethod = console[normalizedLevel]
-            ? console[normalizedLevel]
-            : console.log
+          var realMethod = console[normalizedLevel] || console.log
           if (typeof realMethod === 'function') {
             realMethod.apply(console, args)
           }

diff --git a/packages/rum-core/src/common/service-factory.js b/packages/rum-core/src/common/service-factory.js
@@ -42,7 +42,9 @@ class ServiceFactory {
       return new ConfigService()
     })
     this.registerServiceCreator('LoggingService', function() {
-      return new LoggingService()
+      return new LoggingService({
+        prefix: '[Elastic APM] '
+      })
     })
     this.registerServiceCreator('ApmServer', function() {
       return new ApmServer(

diff --git a/packages/rum-core/src/performance-monitoring/performance-monitoring.js b/packages/rum-core/src/performance-monitoring/performance-monitoring.js
@@ -66,11 +66,6 @@ class PerformanceMonitoring {
       const payload = this.createTransactionPayload(tr)
       if (payload) {
         this._apmServer.addTransaction(payload)
-      } else if (__DEV__) {
-        this._logginService.debug(
-          'Could not create a payload from the Transaction',
-          tr
-        )
       }
     })
 
@@ -217,7 +212,7 @@ class PerformanceMonitoring {
 
     if (!duration) {
       if (__DEV__) {
-        let message = 'Transaction was discarded! '
+        let message = `transaction(${tr.id}, ${tr.name}) was discarded! `
         if (duration === 0) {
           message += `Transaction duration is 0`
         } else {
@@ -231,7 +226,9 @@ class PerformanceMonitoring {
     if (duration > transactionDurationThreshold) {
       if (__DEV__) {
         this._logginService.debug(
-          `Transaction was discarded! Transaction duration (${duration}) is greater than the transactionDurationThreshold configuration (${transactionDurationThreshold})`
+          `transaction(${tr.id}, ${
+            tr.name
+          }) was discarded! Transaction duration (${duration}) is greater than the transactionDurationThreshold configuration (${transactionDurationThreshold})`
         )
       }
       return false
@@ -240,7 +237,9 @@ class PerformanceMonitoring {
     if (tr.spans.length === 0) {
       if (__DEV__) {
         this._logginService.debug(
-          `Transaction was discarded! Transaction does not include any spans`
+          `transaction(${tr.id}, ${
+            tr.name
+          }) was discarded! Transaction does not include any spans`
         )
       }
       return false
@@ -273,7 +272,9 @@ class PerformanceMonitoring {
       if (!wasBrowserResponsive) {
         if (__DEV__) {
           this._logginService.debug(
-            'Transaction was discarded! Browser was not responsive enough during the transaction.',
+            `transaction(${tr.id}, ${
+              tr.name
+            }) was discarded! Browser was not responsive enough during the transaction.`,
             ' duration:',
             duration,
             ' browserResponsivenessCounter:',

diff --git a/packages/rum-core/src/performance-monitoring/transaction-service.js b/packages/rum-core/src/performance-monitoring/transaction-service.js
@@ -33,9 +33,6 @@ import { TRANSACTION_START, TRANSACTION_END } from '../common/constants'
 
 class TransactionService {
   constructor(logger, config) {
-    if (__DEV__ && typeof config === 'undefined') {
-      logger.debug('TransactionService: config is not provided')
-    }
     this._config = config
     this._logger = logger
     this.currentTransaction = undefined
@@ -79,7 +76,7 @@ class TransactionService {
     var interval = this._config.get('browserResponsivenessInterval')
     if (typeof interval === 'undefined') {
       if (__DEV__) {
-        this._logger.debug('browserResponsivenessInterval is undefined!')
+        this._logger.debug('browserResponsivenessInterval config is undefined!')
       }
       return
     }
@@ -125,11 +122,10 @@ class TransactionService {
        */
       if (__DEV__) {
         this._logger.debug(
-          'Redefining the current transaction',
-          tr,
-          name,
-          type,
-          perfOptions
+          `redefining transaction(${tr.id}, ${tr.name}, ${tr.type})`,
+          'to',
+          `(${name}, ${type})`,
+          tr
         )
       }
       /**
@@ -140,7 +136,10 @@ class TransactionService {
       tr.redefine(name, undefined, perfOptions)
     } else {
       if (__DEV__) {
-        this._logger.debug('Ending old transaction', tr)
+        this._logger.debug(
+          `ending previous transaction(${tr.id}, ${tr.name})`,
+          tr
+        )
       }
       tr.end()
       tr = this.createTransaction(name, type, perfOptions)
@@ -180,7 +179,7 @@ class TransactionService {
     tr.onEnd = () => this.handleTransactionEnd(tr)
 
     if (__DEV__) {
-      this._logger.debug('TransactionService.startTransaction', tr)
+      this._logger.debug(`startTransaction(${tr.id}, ${tr.name}, ${tr.type})`)
     }
     this._config.events.send(TRANSACTION_START, [tr])
 
@@ -190,21 +189,24 @@ class TransactionService {
   handleTransactionEnd(tr) {
     return Promise.resolve().then(
       () => {
-        if (this.shouldIgnoreTransaction(tr.name)) {
+        const { name, type } = tr
+        if (this.shouldIgnoreTransaction(name)) {
           if (__DEV__) {
-            this._logger.debug('TransactionService transaction is ignored', tr)
+            this._logger.debug(
+              `transaction(${tr.id}, ${name}, ${type}) is ignored`
+            )
           }
           return
         }
-        if (tr.type === PAGE_LOAD) {
+        if (type === PAGE_LOAD) {
           /**
            * Setting the pageLoadTransactionName via configService.setConfig after
            * transaction has started should also reflect the correct name.
            */
           const pageLoadTransactionName = this._config.get(
             'pageLoadTransactionName'
           )
-          if (tr.name === NAME_UNKNOWN && pageLoadTransactionName) {
+          if (name === NAME_UNKNOWN && pageLoadTransactionName) {
             tr.name = pageLoadTransactionName
           }
         }
@@ -224,12 +226,15 @@ class TransactionService {
         }
         this._config.events.send(TRANSACTION_END, [tr])
         if (__DEV__) {
-          this._logger.debug('TransactionService transaction ended', tr)
+          this._logger.debug(`end transaction(${tr.id}, ${tr.name})`, tr)
         }
       },
       err => {
         if (__DEV__) {
-          this._logger.debug('TransactionService transaction onEnd', err)
+          this._logger.debug(
+            `error ending transaction(${tr.id}, ${tr.name})`,
+            err
+          )
         }
       }
     )
@@ -290,13 +295,16 @@ class TransactionService {
   }
 
   startSpan(name, type, options) {
-    var trans = this.ensureCurrentTransaction()
+    const tr = this.ensureCurrentTransaction()
 
-    if (trans) {
+    if (tr) {
+      const span = tr.startSpan(name, type, options)
       if (__DEV__) {
-        this._logger.debug('TransactionService.startSpan', name, type)
+        this._logger.debug(
+          `startSpan(${name}, ${type})`,
+          `on transaction(${tr.id}, ${tr.name})`
+        )
       }
-      var span = trans.startSpan(name, type, options)
       return span
     }
   }
@@ -306,7 +314,10 @@ class TransactionService {
     if (tr) {
       var taskId = tr.addTask(taskId)
       if (__DEV__) {
-        this._logger.debug('TransactionService.addTask', taskId)
+        this._logger.debug(
+          `addTask(${taskId})`,
+          `on transaction(${tr.id}, ${tr.name})`
+        )
       }
     }
     return taskId
@@ -317,7 +328,10 @@ class TransactionService {
     if (tr) {
       tr.removeTask(taskId)
       if (__DEV__) {
-        this._logger.debug('TransactionService.removeTask', taskId)
+        this._logger.debug(
+          `removeTask(${taskId})`,
+          `on transaction(${tr.id}, ${tr.name})`
+        )
       }
     }
   }

diff --git a/packages/rum-core/test/performance-monitoring/performance-monitoring.spec.js b/packages/rum-core/test/performance-monitoring/performance-monitoring.spec.js
@@ -203,39 +203,39 @@ describe('PerformanceMonitoring', function() {
       transactionDurationThreshold: 200
     })
     spyOn(logger, 'debug').and.callThrough()
-    const transaction1 = new Transaction()
+    const transaction1 = new Transaction('test', 'custom', { id: 1 })
     transaction1.end()
     transaction1._start = 0
     transaction1._end = 201
     expect(transaction1.duration()).toBe(201)
     expect(performanceMonitoring.filterTransaction(transaction1)).toBe(false)
     expect(logger.debug).toHaveBeenCalledWith(
-      'Transaction was discarded! Transaction duration (201) is greater than the transactionDurationThreshold configuration (200)'
+      'transaction(1, test) was discarded! Transaction duration (201) is greater than the transactionDurationThreshold configuration (200)'
     )
     logger.debug.calls.reset()
 
-    const transaction2 = new Transaction()
+    const transaction2 = new Transaction('test2', 'custom', { id: 2 })
     transaction2.end()
     transaction2._end = transaction2._end + 100
     expect(performanceMonitoring.filterTransaction(transaction2)).toBe(false)
     expect(logger.debug).toHaveBeenCalledWith(
-      'Transaction was discarded! Transaction does not include any spans'
+      'transaction(2, test2) was discarded! Transaction does not include any spans'
     )
     logger.debug.calls.reset()
 
-    const transaction3 = new Transaction()
+    const transaction3 = new Transaction(null, null, { id: 3 })
     expect(performanceMonitoring.filterTransaction(transaction3)).toBe(false)
     expect(logger.debug).toHaveBeenCalledWith(
-      "Transaction was discarded! Transaction wasn't ended"
+      "transaction(3, Unknown) was discarded! Transaction wasn't ended"
     )
     logger.debug.calls.reset()
 
-    const transaction4 = new Transaction()
+    const transaction4 = new Transaction('', '', { id: 4 })
     transaction4.end()
     transaction4._start = transaction4._end = 0
     expect(performanceMonitoring.filterTransaction(transaction4)).toBe(false)
     expect(logger.debug).toHaveBeenCalledWith(
-      'Transaction was discarded! Transaction duration is 0'
+      'transaction(4, Unknown) was discarded! Transaction duration is 0'
     )
   })
 
@@ -248,6 +248,7 @@ describe('PerformanceMonitoring', function() {
     spyOn(logger, 'debug').and.callThrough()
     expect(logger.debug).not.toHaveBeenCalled()
     var tr = new Transaction('transaction', 'transaction', {
+      id: 212,
       transactionSampleRate: 1,
       managed: true,
       checkBrowserResponsiveness: true
@@ -262,7 +263,7 @@ describe('PerformanceMonitoring', function() {
     var wasBrowserResponsive = performanceMonitoring.filterTransaction(tr)
     expect(wasBrowserResponsive).toBe(false)
     expect(logger.debug).toHaveBeenCalledWith(
-      'Transaction was discarded! Browser was not responsive enough during the transaction.',
+      'transaction(212, transaction) was discarded! Browser was not responsive enough during the transaction.',
       ' duration:',
       3000,
       ' browserResponsivenessCounter:',

diff --git a/packages/rum/src/apm-base.js b/packages/rum/src/apm-base.js
@@ -111,14 +111,14 @@ class ApmBase {
           } else {
             const { key, value, allowed } = invalid[0]
             loggingService.warn(
-              `Invalid value "${value}" for ${key}. Allowed: ${allowed}.`
+              `invalid value "${value}" for ${key}. Allowed: ${allowed}.`
             )
           }
         }
         return config
       })
       .catch(error => {
-        loggingService.warn('Failed fetching config:', error)
+        loggingService.warn('failed fetching config:', error)
       })
   }
 
@@ -186,10 +186,10 @@ class ApmBase {
     } else {
       const loggingService = this.serviceFactory.getService('LoggingService')
       const separator = ', '
-      let message = "RUM Agent isn't correctly configured: "
+      let message = "RUM agent isn't correctly configured. "
 
       if (missing.length > 0) {
-        message += 'Missing config - ' + missing.join(separator)
+        message += missing.join(separator) + ' is missing'
         if (invalid.length > 0) {
           message += separator
         }

diff --git a/packages/rum/src/bootstrap.js b/packages/rum/src/bootstrap.js
@@ -42,7 +42,7 @@ export default function bootstrap() {
      * Print this error message only on the browser console
      * on unsupported browser versions
      */
-    console.log('APM: Platform is not supported!')
+    console.log('[Elastic APM] platform is not supported!')
   }
 
   return enabled

diff --git a/packages/rum/test/specs/apm-base.spec.js b/packages/rum/test/specs/apm-base.spec.js
@@ -268,7 +268,7 @@ describe('ApmBase', function() {
       serviceName: ''
     })
     expect(loggingService.error).toHaveBeenCalledWith(
-      `RUM Agent isn't correctly configured: Missing config - serverUrl, serviceName`
+      `RUM agent isn't correctly configured. serverUrl, serviceName is missing`
     )
     const configService = serviceFactory.getService('ConfigService')
     expect(configService.get('active')).toEqual(false)
@@ -279,15 +279,15 @@ describe('ApmBase', function() {
       serviceName: 'abc.def'
     })
     expect(loggingService.error).toHaveBeenCalledWith(
-      `RUM Agent isn't correctly configured: Missing config - serverUrl, serviceName "abc.def" contains invalid characters! (allowed: a-z, A-Z, 0-9, _, -, <space>)`
+      `RUM agent isn't correctly configured. serverUrl is missing, serviceName "abc.def" contains invalid characters! (allowed: a-z, A-Z, 0-9, _, -, <space>)`
     )
 
     logErrorSpy.calls.reset()
     apmBase.config({
       serviceName: 'abc.def'
     })
     expect(loggingService.error).toHaveBeenCalledWith(
-      `RUM Agent isn't correctly configured: serviceName "abc.def" contains invalid characters! (allowed: a-z, A-Z, 0-9, _, -, <space>)`
+      `RUM agent isn't correctly configured. serviceName "abc.def" contains invalid characters! (allowed: a-z, A-Z, 0-9, _, -, <space>)`
     )
   })
 
@@ -349,7 +349,7 @@ describe('ApmBase', function() {
       .fetchCentralConfig()
       .then(() => {
         expect(loggingService.warn).toHaveBeenCalledWith(
-          'Invalid value "NaN" for transactionSampleRate. Allowed: Number between 0 and 1.'
+          'invalid value "NaN" for transactionSampleRate. Allowed: Number between 0 and 1.'
         )
         expect(configService.get('transactionSampleRate')).toBe(1)
 

diff --git a/packages/rum/test/specs/index.spec.js b/packages/rum/test/specs/index.spec.js
@@ -53,7 +53,9 @@ describe('index', function() {
     delete require.cache[require.resolve('../../src/bootstrap')]
     require('../../src/')
 
-    expect(console.log).toHaveBeenCalledWith('APM: Platform is not supported!')
+    expect(console.log).toHaveBeenCalledWith(
+      '[Elastic APM] platform is not supported!'
+    )
 
     window.performance.now = nowFn
   })