Sequence logs (#18)

* getting sequence logs by looking into nested activation IDs

* add: unit tests + refactoring

* fix: change test name

* fix: lint

* fix: coverage

* Preventing dup logs and some error handling

Co-authored-by: Arjun Raj <rajarju@gmail.com>
Co-authored-by: Arjun Raj <rajarju@users.noreply.github.com>

src/utils.js

@@ -321,42 +321,102 @@ async function printFilteredActionLogs (runtime, logger, limit, filterActions =
     })
   }
 
+  const activationsLogged = []
   // Getting and printing activation logs
   for (let i = (activations.length - 1); i >= 0; i--) {
     const activation = activations[i]
     lastActivationTime = activation.start
     if (lastActivationTime > startTime) {
-      const allResults = []
-      let results
-      try {
-        results = await runtime.activations.logs({ activationId: activation.activationId })
-      } catch (err) { // Happens in some cases such as trying to get logs of a trigger activation
-        // TODO: Trigger logs can be obtained from activation result but will need some formatting for the timestamp
-        // results = await runtime.activations.get({ activationId: activation.activationId })
-        continue
+      await printLogs(activation, runtime)
+    }
+  }
+  return { lastActivationTime }
+
+  /**
+   * Check if an activation entry is for a sequence.
+   *
+   * @param {*} activation activation log entry
+   * @returns {boolean} isSequenceActivation
+   */
+  function isSequenceActivation (activation) {
+    if (activation.annotations && activation.annotations.length) {
+      return activation.annotations.some(item => (item.key === 'kind' && item.value === 'sequence'))
+    }
+    return false
+  }
+
+  /**
+   * Print activation logs
+   * @param {*} activation
+   * @param {*} runtime
+   */
+  async function printActivationLogs (activation, runtime) {
+    const results = []
+    let retValue
+    try {
+      if (activationsLogged.includes(activation.activationId)) {
+        // Happens when this activation is already covered through a sequence
+        return
+      } else {
+        activationsLogged.push(activation.activationId)
       }
-      if (results.logs.length > 0) {
+      retValue = await runtime.activations.logs({ activationId: activation.activationId })
+      if (retValue.logs.length > 0) {
         activation.annotations.forEach((annotation) => {
           if (annotation.key === 'path') {
             logFunc(annotation.value + ':' + activation.activationId)
           }
         })
-        results.logs.forEach(function (logMsg) {
+        retValue.logs.forEach(function (logMsg) {
           if (strip) {
-            allResults.push(stripLog(logMsg))
+            results.push(stripLog(logMsg))
           } else {
-            allResults.push(logMsg)
+            results.push(logMsg)
           }
         })
       }
-      allResults.sort()
-      allResults.forEach((logMsg) => {
-        logFunc(logMsg)
-        // logFunc()  // new line ?
-      })
+    } catch (err) { // Happens in some cases such as trying to get logs of a trigger activation
+      // TODO: Trigger logs can be obtained from activation result but will need some formatting for the timestamp
+      // retValue = await runtime.activations.get({ activationId: activation.activationId })
+      return
+    }
+    results.sort()
+    results.forEach((logMsg) => {
+      logFunc(logMsg)
+      // logFunc()  // new line ?
+    })
+  }
+
+  /**
+   * Print sequence logs
+   * @param {*} activation
+   * @param {*} runtime
+   */
+  async function printSequenceLogs (activation, runtime) {
+    try {
+      const seqActivation = await runtime.activations.get(activation.activationId)
+      for (const seqItemActivationId of seqActivation.logs) {
+        const seqItemActivation = await runtime.activations.get(seqItemActivationId)
+        await printLogs(seqItemActivation, runtime)
+      }
+    } catch (err) {
+      // Happens when either the sequence or one of the actions in the sequence fails with 'application error'
+      // Ignore
+    }
+  }
+
+  /**
+   * Print logs
+   * @param {*} activation
+   * @param {*} runtime
+   */
+  async function printLogs (activation, runtime) {
+    if (isSequenceActivation(activation)) {
+      await printSequenceLogs(activation, runtime)
+    } else {
+      await printActivationLogs(activation, runtime)
     }
   }
-  return { lastActivationTime }
 }
 
 /**
@@ -584,7 +644,7 @@ function createKeyValueObjectFromFile (file) {
  * @param {Array} sequenceAction the sequence action array
  * @returns {object} the object representation of the sequence
  */
-function createComponentsfromSequence (sequenceAction) {
+function createComponentsFromSequence (sequenceAction) {
   const fqn = require('openwhisk-fqn')
   const objSequence = {}
   objSequence.kind = 'sequence'
@@ -595,6 +655,17 @@ function createComponentsfromSequence (sequenceAction) {
   return objSequence
 }
 
+/* istanbul ignore next */
+/**
+ * @alias createComponentsFromSequence
+ * @deprecated use `createComponentsFromSequence`
+ * @param {Array} sequenceAction the sequence action array
+ * @returns {object} the object representation of the sequence
+ */
+function createComponentsfromSequence (sequenceAction) {
+  return createComponentsFromSequence(sequenceAction)
+}
+
 /**
  * @description Creates a union of two objects
  * @param {object} firstObject the object to merge into
@@ -1487,7 +1558,7 @@ async function undeployPackage (entities, ow, logger) {
  */
 async function syncProject (projectName, manifestPath, manifestContent, entities, ow, logger, imsOrgId, deleteEntities = true) {
   // find project hash from server based on entities in the manifest file
-  const hashProjectSynced = await findProjectHashonServer(ow, projectName)
+  const hashProjectSynced = await findProjectHashOnServer(ow, projectName)
 
   // compute the project hash from the manifest file
   const projectHash = getProjectHash(manifestContent, manifestPath)
@@ -1630,7 +1701,7 @@ function getProjectHash (manifestContent, manifestPath) {
  * @param {string} projectName the project name
  * @returns {Promise<string>} the project hash, or '' if not found
  */
-async function findProjectHashonServer (ow, projectName) {
+async function findProjectHashOnServer (ow, projectName) {
   let projectHash = ''
   const options = {}
   // check for package with the projectName in manifest File and if found -> return the projectHash on the server
@@ -1683,6 +1754,20 @@ async function findProjectHashonServer (ow, projectName) {
   return projectHash
 }
 
+/* istanbul ignore next */
+/**
+ * Retrieve the project hash from a deployed managed project.
+ *
+ * @deprecated use `findProjectHashOnServer`
+ * @alias findProjectHashOnServer
+ * @param {object} ow the OpenWhisk client object
+ * @param {string} projectName the project name
+ * @returns {Promise<string>} the project hash, or '' if not found
+ */
+async function findProjectHashonServer (ow, projectName) {
+  return findProjectHashOnServer(ow, projectName)
+}
+
 /**
  * @param root
  * @param p
@@ -1897,6 +1982,7 @@ module.exports = {
   getKeyValueObjectFromMergedParameters,
   parsePathPattern,
   parsePackageName,
+  createComponentsFromSequence,
   createComponentsfromSequence,
   processInputs,
   createKeyValueInput, /* internal */
@@ -1915,6 +2001,7 @@ module.exports = {
   setPaths,
   getProjectEntities,
   syncProject,
+  findProjectHashOnServer,
   findProjectHashonServer,
   getProjectHash,
   addManagedProjectAnnotations,

test/print.action.logs.test.js

@@ -13,10 +13,12 @@ jest.mock('../src/RuntimeAPI')
 const ioruntime = require('../src/RuntimeAPI')
 const owListActivationMock = jest.fn()
 const owLogsActivationMock = jest.fn()
+const owGetActivationMock = jest.fn()
 const owMock = {
   activations: {
     list: owListActivationMock,
-    logs: owLogsActivationMock
+    logs: owLogsActivationMock,
+    get: owGetActivationMock
   }
 }
 ioruntime.mockImplementation(() => {
@@ -43,6 +45,7 @@ describe('printActionLogs', () => {
     ioruntime.mockClear()
     owListActivationMock.mockReset()
     owLogsActivationMock.mockReset()
+    owGetActivationMock.mockReset()
     // runtimeLibUtils.printFilteredActionLogs.mockReset()
   })
 
@@ -81,6 +84,124 @@ describe('printActionLogs', () => {
     expect(logger).not.toHaveBeenCalled()
   })
 
+  test('with sequence action', async () => {
+    owListActivationMock.mockResolvedValue([
+      {
+        activationId: 123,
+        start: 555555,
+        name: 'one',
+        annotations: [{ key: 'kind', value: 'sequence' }],
+        logs: [
+          321
+        ]
+      }
+    ])
+    owGetActivationMock.mockImplementation(activationId => {
+      if (activationId === 123) {
+        // Sub sequence activation
+        return {
+          activationId: 123,
+          start: 555555,
+          name: 'one',
+          annotations: [{ key: 'kind', value: 'sequence' }],
+          logs: [
+            321
+          ]
+        }
+      } else {
+        // Stub action activation
+        return {
+          activationId: 321,
+          start: 555555,
+          name: 'one',
+          logs: []
+        }
+      }
+    })
+
+    owLogsActivationMock.mockResolvedValue({ logs: [] })
+    await printActionLogs(fakeConfig, logger, 3)
+    expect(owListActivationMock).toHaveBeenCalledWith({ limit: 3, skip: 0 })
+    expect(owGetActivationMock).toHaveBeenCalledTimes(2)
+    expect(owLogsActivationMock).toHaveBeenCalledTimes(1)
+    // reverse order
+    expect(owLogsActivationMock).toHaveBeenNthCalledWith(1, { activationId: 321 })
+    expect(logger).not.toHaveBeenCalled()
+  })
+
+  test('with sequence action - error', async () => {
+    owListActivationMock.mockResolvedValue([
+      {
+        activationId: 123,
+        start: 555555,
+        name: 'one',
+        annotations: [{ key: 'kind', value: 'sequence' }],
+        logs: [
+          321
+        ]
+      }
+    ])
+    owGetActivationMock.mockImplementation(activationId => {
+      throw new Error()
+    })
+
+    // owLogsActivationMock.mockResolvedValue({ logs: [] })
+    await printActionLogs(fakeConfig, logger, 3)
+    expect(owListActivationMock).toHaveBeenCalledWith({ limit: 3, skip: 0 })
+    expect(owGetActivationMock).toHaveBeenCalledTimes(1)
+  })
+
+  test('with an action and a sequence that uses the same action - should not log twice', async () => {
+    owListActivationMock.mockResolvedValue([
+      {
+        activationId: 123,
+        start: 555555,
+        name: 'oneseq',
+        annotations: [{ key: 'kind', value: 'sequence' }],
+        logs: [
+          '124'
+        ]
+      },
+      {
+        activationId: 124,
+        start: 555555,
+        name: 'oneaction',
+        annotations: [{ key: 'path', value: 'action1' }],
+        logs: [
+          'dummy'
+        ]
+      }
+    ])
+    owGetActivationMock.mockImplementation(activationId => {
+      if (activationId === 123) {
+        // Sub sequence activation
+        return {
+          activationId: 123,
+          start: 555555,
+          name: 'oneseq',
+          annotations: [{ key: 'kind', value: 'sequence' }],
+          logs: [
+            124
+          ]
+        }
+      } else {
+        // Stub action activation
+        return {
+          activationId: 124,
+          start: 555555,
+          name: 'oneaction',
+          logs: []
+        }
+      }
+    })
+
+    owLogsActivationMock.mockResolvedValue({ logs: [] })
+    await printActionLogs(fakeConfig, logger, 3)
+    expect(owListActivationMock).toHaveBeenCalledWith({ limit: 3, skip: 0 })
+    expect(owGetActivationMock).toHaveBeenCalledTimes(2)
+    expect(owLogsActivationMock).toHaveBeenCalledTimes(1) // Only once
+  })
+
   test('(config, limit=45, logger) and 3 activations and logs for 2 of them', async () => {
     owListActivationMock.mockResolvedValue([
       { activationId: 123, start: 555555, name: 'one', annotations: [] },
@@ -141,7 +262,7 @@ describe('printActionLogs', () => {
 
   test('(config, limit=45, no logger) and 1 activation and 1 log', async () => {
     const spy = jest.spyOn(console, 'log')
-    spy.mockImplementation(() => {})
+    spy.mockImplementation(() => { })
 
     owListActivationMock.mockResolvedValue([
       { activationId: 123, start: 555555, name: 'one', annotations: [] }
@@ -164,6 +285,7 @@ describe('printActionLogs', () => {
 
     spy.mockRestore()
   })
+
   test('with filterActions (specific actions)', async () => {
     owListActivationMock.mockResolvedValue([
       { activationId: 123, start: 555555, name: 'one', annotations: [{ key: 'path', value: 'ns/pkg1/one' }] },