adobe/openwhisk-action-logger

Logger for openwhisk actions.

openwhisk-action-logger's Issues

Add __CFBundleIdentifier to the list of ignored parameters to trace on macOS

When starting a debug session, I always see the following being logged in the Debug Console:

Trace: { params: { __CFBundleIdentifier: 'com.googlecode.iterm2' } } before
    at .../node_modules/@adobe/openwhisk-action-logger/src/logger.js:270:9
    at .../node_modules/@adobe/openwhisk-action-logger/src/logger.js:229:12
    at .../node_modules/cls-hooked/context.js:118:13
    at Namespace.run (.../node_modules/cls-hooked/context.js:97:5)
    ...

The environment variable __CFBundleIdentifier seems to have appeared lately and contains the name of the terminal application being used (it reads __CFBundleIdentifier=com.apple.Terminal when using macOS's default terminal).

It would be nice if the list of parameters being ignored in

openwhisk-action-logger/src/logger.js

Lines 257 to 264 in c983a43

	const disclosedParams = { ...params };
	Object.keys(disclosedParams)
	.forEach((key) => {
	if (key.match(/^[A-Z0-9_]+$/)) {
	delete disclosedParams[key];
	}
	});
	delete disclosedParams.__ow_logger;

could contain that identifier as well.

Dependency Dashboard

This issue lists Renovate updates and detected dependencies. Read the Dependency Dashboard docs to learn more.

This repository currently has no open or pending branches.

Detected dependencies

circleci

.circleci/config.yml

• circleci/node 14

github-actions

.github/workflows/semantic-release.yaml

• actions/checkout v3
• actions/setup-node v3

.github/workflows/semver-check.yaml

npm

package.json

• @adobe/helix-log 6.0.0
• cls-hooked ^4.2.2
• @adobe/eslint-config-helix 1.3.2
• @adobe/openwhisk-action-utils 4.4.8
• @semantic-release/changelog 6.0.1
• @semantic-release/git 10.0.1
• codecov 3.8.3
• eslint 8.25.0
• eslint-plugin-header 3.1.1
• eslint-plugin-import 2.26.0
• ghooks 2.0.4
• jsdoc-to-markdown 7.1.1
• lint-staged 13.0.3
• mocha 10.0.0
• mocha-junit-reporter 2.1.0
• nock 13.2.9
• nyc 15.1.0
• semantic-release 19.0.5
• node >= 8.3.0

---

• Check this box to trigger a request for Renovate to run again on this repository

remove local env config support

the local config support is not used anymore and should be removed.

Add url information to the logs

The CoralogixLogger and the PapertrailLogger automatically add an ow object to the log message:

ow: {
          activationId: process.env.__OW_ACTIVATION_ID,
          actionName: process.env.__OW_ACTION_NAME,
          transactionId: process.env.__OW_TRANSACTION_ID
        },

This is really useful and this information could be enhanced with a header property containing the value of the incoming params.__ow_headers.
This would be required to achieve: adobe/helix-home#70

Based on @tripodsan feedback, the full ow object (+ the new headers) should be computed directly in the generic helix-log logger. (details adobe/openwhisk-action-utils@63a5291#commitcomment-35805854)

I started to prototype this but I hit 2 road blockers:

• I do not really understand the logger structure, the final __ow_logger object contains a nested structure of 4 level of MultiLoggers. This should be fixed with adobe/openwhisk-action-utils#26
• There is no generic sanitize method to prevent the headers to contain secrets. See adobe/openwhisk-action-utils#27

Provide log parameters sanitisation as a service

Consumers of the openwhisk-action-utils API have to worry about what they log and sanitise their secret. This will either end-up into code duplication or secrets being exposed in the logs because they will forget.
For example: https://github.com/adobe/helix-dispatch/blob/master/src/index.js#L51-L58

This was supposed to be addressed by adobe/helix-log#44 but since I managed to output many secrets yesterday, I think this is not properly supported and at least for sure it is not tested.

I do not know if this should be in https://github.com/adobe/helix-log or in this project, I leave to our "log architects" (@koraa @tripodsan @trieloff) to decide what is the best location for this.

My only requirement is that when I log:

{
  MY_SECRET_KEY: 'mykeyvalue'
} 

log outputs is:

{
  MY_SECRET_KEY: 'undisclosed secret'
} 

The text does not matter but the key should not be removed so that I know it is there but I cannot read the value! If we remove the key (like here https://github.com/adobe/openwhisk-action-utils/blob/master/src/logger.js#L205), I do not know if the key was not transported to the action, if I forgot it in the service config or if I use a format which is filtered out for a param to not filter like MY_DEBUG_PARAM.

logger level inconsistencies

Follow up of my researches for adobe/openwhisk-action-builder#106
I have been playing with the log levels and I found out multiple inconsistencies. I created:

• https://github.com/kptdobe/helix-dummy/tree/debug
• https://github.com/kptdobe/helix-dummy/tree/trace
• https://github.com/kptdobe/helix-dummy/tree/silly

which contains the same code, only difference is the LOG_LEVEL set to the corresponding branch name.

Switching between those branches and redeploying the action leads to multiple inconsistencies:

I use the line rm -fr dist; npm run deploy >/dev/null 2>&1; curl https://adobeioruntime.net/api/v1/web/acapt/helix-services-private/[email protected]; sleep 7; wsk activation logs --last to

1. clean up the dist folder and make sure I have the last code deploy
2. deploy the action
3. call the action
4. wait 7s (logs take some time to appear)
5. retrieve the latest activation logs

Here is a full script:

# run debug version
$ git checkout debug
$ rm -fr dist; npm run deploy >/dev/null 2>&1; curl https://adobeioruntime.net/api/v1/web/acapt/helix-services-private/[email protected]; sleep 7; wsk activation logs --last
Done. LOG_LEVEL parameter: debug. Logger level: silly.
2020-01-31T10:03:27.068Z       stderr: [ERROR] log.error
2020-01-31T10:03:27.068Z       stderr: [WARN] log.warn
2020-01-31T10:03:27.069Z       stderr: [INFO] log.info
2020-01-31T10:03:27.069Z       stderr: [DEBUG] log.debug
# -> result as expected
# run trace version
$ git checkout trace
$ rm -fr dist; npm run deploy >/dev/null 2>&1; curl https://adobeioruntime.net/api/v1/web/acapt/helix-services-private/[email protected]; sleep 7; wsk activation logs --last
Done. LOG_LEVEL parameter: trace. Logger level: silly.
2020-01-31T10:04:22.149Z       stderr: [TRACE] before { params: { __ow_headers: { accept: '*/*', connection: 'close', host: 'controller-a', 'perf-br-req-in': '1580465062.135', 'user-agent': 'curl/7.54.0', 'x-forwarded-for': '91.171.237.190, 10.250.205.238', 'x-forwarded-host': 'adobeioruntime.net', 'x-forwarded-port': '443', 'x-forwarded-proto': 'https', 'x-real-ip': '10.250.205.238', 'x-request-id': 'oV7T8FdYXnipfm2P7Jtn2YQpDNP7F5kv' }, __ow_method: 'get', __ow_path: '' } }
2020-01-31T10:04:22.150Z       stderr: [ERROR] log.error
2020-01-31T10:04:22.150Z       stderr: [WARN] log.warn
2020-01-31T10:04:22.150Z       stderr: [INFO] log.info
2020-01-31T10:04:22.150Z       stderr: [DEBUG] log.debug
2020-01-31T10:04:22.151Z       stderr: [TRACE] log.trace
2020-01-31T10:04:22.151Z       stderr: [TRACE] result { result: { body: 'Done. LOG_LEVEL parameter: trace. Logger level: silly.\n' } }
# -> result as expected
# run silly version
$ git checkout silly
$ rm -fr dist; npm run deploy >/dev/null 2>&1; curl https://adobeioruntime.net/api/v1/web/acapt/helix-services-private/[email protected]; sleep 7; wsk activation logs --last
Done. LOG_LEVEL parameter: silly. Logger level: silly.
2020-01-31T10:05:04.731Z       stderr: [TRACE] before { params: { __ow_headers: { accept: '*/*', connection: 'close', host: 'controller-a', 'perf-br-req-in': '1580465104.717', 'user-agent': 'curl/7.54.0', 'x-forwarded-for': '91.171.237.190, 10.250.205.238', 'x-forwarded-host': 'adobeioruntime.net', 'x-forwarded-port': '443', 'x-forwarded-proto': 'https', 'x-real-ip': '10.250.205.238', 'x-request-id': 'oL3uD45j1KnQ6mXt3xgoTCbTc4qsUcC4' }, __ow_method: 'get', __ow_path: '' } }
2020-01-31T10:05:04.731Z       stderr: [ERROR] log.error
2020-01-31T10:05:04.731Z       stderr: [WARN] log.warn
2020-01-31T10:05:04.732Z       stderr: [INFO] log.info
2020-01-31T10:05:04.732Z       stderr: [DEBUG] log.debug
2020-01-31T10:05:04.732Z       stderr: [TRACE] log.trace
2020-01-31T10:05:04.733Z       stderr: [TRACE] result { result: { body: 'Done. LOG_LEVEL parameter: silly. Logger level: silly.\n' } }
# -> log.silly is missing!
# run debug version again
$ git checkout debug
$ rm -fr dist; npm run deploy >/dev/null 2>&1; curl https://adobeioruntime.net/api/v1/web/acapt/helix-services-private/[email protected]; sleep 7; wsk activation logs --last
Done. LOG_LEVEL parameter: debug. Logger level: silly.
$
# -> no log at all!!

Multiple issues:

1. log.silly never outputs something
2. __ow_logger.logger.level is always silly (which might be expected) - would be great to adjust the code to output the real logger level
3. More critical: I sometimes reach the point where no log is coming anymore (whatever is the level), even after a new deploy and only option is to increment the action version, like if the logger is completely broken on runtime (might be due to the fact we use a share object)

cc @tripodsan

Action Required: Fix Renovate Configuration

There is an error with this repository's Renovate configuration that needs to be fixed. As a precaution, Renovate will stop PRs until it is resolved.

Error type: undefined. Note: this is a nested preset so please contact the preset author if you are unable to fix it yourself.

allow the set the overall log-level

Add a new level parameter to init() and logger() that can set the overall log-level.
if none specified it falls back to params.LOG_LEVEL and eventually to info.

Use helix-log SimpleInterface instead of bunyan for __ow_logger

ensure that log methods are bound to the logger

Archive repository?

do we still need this?

https://github.com/adobe/helix-universal-logger is the successor to use with helix-universal

local .env file is not parsed correctly

The following line:

openwhisk-action-logger/src/logger.js

Line 60 in ecb6d9d

...dotenv.parse(path.resolve(process.cwd(), '.env')),

looks wrong, as it does not parse the contents of the .env file, but its path.

Add a better way to inject log fields

Currently it is not possible for the init script to add more dynamic fields. The current activationId is only possible, because it uses process.env.

I think using the concept of a child logger that sets the fields in init() based on the params would be more powerful.