Merge pull request #1201 from clearlydefined/ljones140/reduce-logging

Ljones140/reduce logging
clearlydefined · Oct 17, 2024 · 0787868 · 0787868
2 parents 79c4bdc + 396f358
commit 0787868
Show file tree

Hide file tree

Showing 5 changed files with 37 additions and 25 deletions.
diff --git a/business/definitionService.js b/business/definitionService.js
@@ -70,6 +70,7 @@ class DefinitionService {
     const existing = await this._cacheExistingAside(coordinates, force)
     let result
     if (get(existing, '_meta.schemaVersion') === currentSchema) {
+      // Log line used for /status page insights
       this.logger.info('computed definition available', { coordinates: coordinates.toString() })
       result = existing
     } else result = force ? await this.computeAndStore(coordinates) : await this.computeStoreAndCurate(coordinates)
@@ -83,10 +84,10 @@ class DefinitionService {
    */
   async getStored(coordinates) {
     const cacheKey = this._getCacheKey(coordinates)
-    this.logger.info('1:Redis:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+    this.logger.debug('1:Redis:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
     const cached = await this.cache.get(cacheKey)
     if (cached) return cached
-    this.logger.info('2:blob+mongoDB:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+    this.logger.debug('2:blob+mongoDB:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
     const stored = await this.definitionStore.get(coordinates)
     if (stored) this._setDefinitionInCache(cacheKey, stored)
     return stored
@@ -100,7 +101,7 @@ class DefinitionService {
   async _setDefinitionInCache(cacheKey, itemToStore) {
     // 1000 is a magic number here -- we don't want to cache very large definitions, as it can impact redis ops
     if (itemToStore.files && itemToStore.files.length > 1000) {
-      this.logger.info('Skipping caching for key', { coordinates: itemToStore.coordinates.toString() })
+      this.logger.debug('Skipping caching for key', { coordinates: itemToStore.coordinates.toString() })
       return
     }
 
@@ -131,9 +132,9 @@ class DefinitionService {
     const result = {}
     const promises = coordinatesList.map(
       throat(10, async coordinates => {
-        this.logger.info(`1:1:notice_generate:get_single_start:${coordinates}`, { ts: new Date().toISOString() })
+        this.logger.debug(`1:1:notice_generate:get_single_start:${coordinates}`, { ts: new Date().toISOString() })
         const definition = await this.get(coordinates, null, force, expand)
-        this.logger.info(`1:1:notice_generate:get_single_end:${coordinates}`, { ts: new Date().toISOString() })
+        this.logger.debug(`1:1:notice_generate:get_single_end:${coordinates}`, { ts: new Date().toISOString() })
         if (!definition) return
         const key = definition.coordinates.toString()
         result[key] = definition
@@ -217,7 +218,7 @@ class DefinitionService {
 
   async computeStoreAndCurate(coordinates) {
     // one coordinate a time through this method so no duplicate auto curation will be created.
-    this.logger.info('3:memory_lock:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+    this.logger.debug('3:memory_lock:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
     while (computeLock.get(coordinates.toString())) await new Promise(resolve => setTimeout(resolve, 500))
     try {
       computeLock.set(coordinates.toString(), true)
@@ -245,20 +246,22 @@ class DefinitionService {
     // Note that curation is a tool so no tools really means there the definition is effectively empty.
     const tools = get(definition, 'described.tools')
     if (!tools || tools.length === 0) {
+      // Log line used for /status page insights
       this.logger.info('definition not available', { coordinates: coordinates.toString() })
       this._harvest(coordinates) // fire and forget
       return definition
     }
+    // Log line used for /status page insights
     this.logger.info('recomputed definition available', { coordinates: coordinates.toString() })
     await this._store(definition)
     return definition
   }
 
   async _harvest(coordinates) {
     try {
-      this.logger.info('trigger_harvest:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+      this.logger.debug('trigger_harvest:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
       await this.harvestService.harvest({ tool: 'component', coordinates }, true)
-      this.logger.info('trigger_harvest:end', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+      this.logger.debug('trigger_harvest:end', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
     } catch (error) {
       this.logger.info('failed to harvest from definition service', {
         crawlerError: error,
@@ -282,26 +285,35 @@ class DefinitionService {
    * @returns {Definition} The fully rendered definition
    */
   async compute(coordinates, curationSpec) {
-    this.logger.info('4:compute:blob:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+    this.logger.debug('4:compute:blob:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
     const raw = await this.harvestStore.getAll(coordinates)
-    this.logger.info('4:compute:blob:end', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+    this.logger.debug('4:compute:blob:end', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
     coordinates = this._getCasedCoordinates(raw, coordinates)
-    this.logger.info('5:compute:summarize:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+    this.logger.debug('5:compute:summarize:start', {
+      ts: new Date().toISOString(),
+      coordinates: coordinates.toString()
+    })
     const summaries = await this.summaryService.summarizeAll(coordinates, raw)
-    this.logger.info('6:compute:aggregate:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+    this.logger.debug('6:compute:aggregate:start', {
+      ts: new Date().toISOString(),
+      coordinates: coordinates.toString()
+    })
     const aggregatedDefinition = (await this.aggregationService.process(summaries, coordinates)) || {}
-    this.logger.info('6:compute:aggregate:end', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+    this.logger.debug('6:compute:aggregate:end', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
     aggregatedDefinition.coordinates = coordinates
     this._ensureToolScores(coordinates, aggregatedDefinition)
     const definition = await this.curationService.apply(coordinates, curationSpec, aggregatedDefinition)
-    this.logger.info('9:compute:calculate:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+    this.logger.debug('9:compute:calculate:start', {
+      ts: new Date().toISOString(),
+      coordinates: coordinates.toString()
+    })
     this._finalizeDefinition(coordinates, definition)
     this._ensureCuratedScores(definition)
     this._ensureFinalScores(definition)
     // protect against any element of the compute producing an invalid definition
     this._ensureNoNulls(definition)
     this._validate(definition)
-    this.logger.info('9:compute:calculate:end', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+    this.logger.debug('9:compute:calculate:end', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
     return definition
   }
 

diff --git a/providers/curation/github.js b/providers/curation/github.js
@@ -678,12 +678,12 @@ ${this._formatDefinitions(patch.patches)}`
    */
   async _getCurations(coordinates, pr = null) {
     const path = this._getCurationPath(coordinates)
-    this.logger.info('7:compute:curation_source:start', {
+    this.logger.debug('7:compute:curation_source:start', {
       ts: new Date().toISOString(),
       coordinates: coordinates.toString()
     })
     const tree = await this._getCurationTree(pr)
-    this.logger.info('7:compute:curation_source:end', {
+    this.logger.debug('7:compute:curation_source:end', {
       ts: new Date().toISOString(),
       coordinates: coordinates.toString()
     })
@@ -692,12 +692,12 @@ ${this._formatDefinitions(patch.patches)}`
     )
     const blob = get(tree, treePath)
     if (!blob) return null
-    this.logger.info('8:compute:curation_blob:start', {
+    this.logger.debug('8:compute:curation_blob:start', {
       ts: new Date().toISOString(),
       coordinates: coordinates.toString()
     })
     const data = await this.smartGit.blob(blob.object)
-    this.logger.info('8:compute:curation_blob:end', {
+    this.logger.debug('8:compute:curation_blob:end', {
       ts: new Date().toISOString(),
       coordinates: coordinates.toString()
     })

diff --git a/providers/logging/winstonConfig.js b/providers/logging/winstonConfig.js
@@ -11,7 +11,7 @@ function factory(options) {
   const realOptions = options || {
     key: config.get('APPINSIGHTS_INSTRUMENTATIONKEY'),
     echo: false,
-    level: 'info'
+    level: config.get('APPINSIGHTS_EXPORT_LOG_LEVEL') || 'info'
   }
   mockInsights.setup(realOptions.key || 'mock', realOptions.echo)
   const result = new winston.Logger()

diff --git a/routes/definitions.js b/routes/definitions.js
@@ -58,11 +58,11 @@ async function getDefinition(request, response) {
   const pr = request.params.pr
   const force = request.query.force
   const expand = request.query.expand === '-files' ? '-files' : null // only support '-files' for now
-  log.info('get_definition:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+  log.debug('get_definition:start', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
   const result = await definitionService.get(coordinates, pr, force, expand)
-  log.info('get_definition:prepared', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+  log.debug('get_definition:prepared', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
   response.status(200).send(result)
-  log.info('get_definition:sent', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
+  log.debug('get_definition:sent', { ts: new Date().toISOString(), coordinates: coordinates.toString() })
 }
 
 // Get a list of autocomplete suggestions of components for which we have any kind of definition.
@@ -119,7 +119,7 @@ async function listDefinitions(request, response) {
   const expand = request.query.expand === '-files' ? '-files' : null // only support '-files' for now
   try {
     // Tempoarily adding this verbose logging to find perf issues
-    log.info('POSTing to /definitions', {
+    log.debug('POSTing to /definitions', {
       ts: new Date().toISOString(),
       requestParams: request.params,
       normalizedCoordinates,

diff --git a/test/business/definitionServiceTest.js b/test/business/definitionServiceTest.js
@@ -347,7 +347,7 @@ function setup(definition, coordinateSpec, curation) {
   const summary = { summarizeAll: () => Promise.resolve(null) }
   const aggregator = { process: () => Promise.resolve(definition) }
   const service = DefinitionService(harvestStore, harvestService, summary, aggregator, curator, store, search, cache)
-  service.logger = { info: sinon.stub() }
+  service.logger = { info: sinon.stub(), debug: sinon.stub() }
   service._harvest = sinon.stub()
   const coordinates = EntityCoordinates.fromString(coordinateSpec || 'npm/npmjs/-/test/1.0')
   return { coordinates, service }