Debugging custom promise types

[larsewi]

When debugging custom promise types I use the following command

$ cf-agent -KId /var/cfengine/masterfiles/services/my_policy.cf #policy file using my custom promise module

which produces a lot of noise. Sometimes I'm only interested in log messages from the custom promise module. Thus, I'm wondering if there is some way to only capture these log messages?

E.g. the following is a bit redundant

   debug: Received line from module: 'log_debug=some log message'
   debug: some log message

It can be a bit confusing when cfengine.py catches an unhandled exception, logging each line from the stack trace, line by line, twice.

I guess running the module without cf-agent is a possible answer to this question. But I find it a bit sub-optimal.

[olehermanse]

How to only see log messages from module?

Sometimes I'm only interested in log messages from the custom promise module.

Currently not possible, built-in, but you can make a workaround:

$ /var/cfengine/bin/cf-agent -KId test.cf | grep -A1 "Received line from module\: 'log_" | grep --invert-match "Received line from module"
    info: Cloning 'https://github.com/cfengine/masterfiles' -> '/opt/cfengine/masterfiles'...
    info: Successfully cloned 'https://github.com/cfengine/masterfiles' -> '/opt/cfengine/masterfiles'

Assuming the module doesn't use JSON protocol for logging, and that the log messages appear directly after the line received messages.

Details

We don't have separate levels of debug logging, which could help in this way.

E.g. the following is a bit redundant

   debug: Received line from module: 'log_debug=some log message'
   debug: some log message

Maybe, but the first line is very useful to see exactly what data is being received from the module, the second is just logging working as intended.

I guess running the module without cf-agent is a possible answer to this question. But I find it a bit sub-optimal.

MIght be a good approach in many situations.

Filtering log output with grep

Here's some more nifty examples.

log_ lines received:

$ /var/cfengine/bin/cf-agent -KId test.cf | grep "Received line from module\: 'log_"
   debug: Received line from module: 'log_info=Cloning 'https://github.com/cfengine/masterfiles' -> '/opt/cfengine/masterfiles'...'
   debug: Received line from module: 'log_info=Successfully cloned 'https://github.com/cfengine/masterfiles' -> '/opt/cfengine/masterfiles''

log_ lines received and the following line:

$ /var/cfengine/bin/cf-agent -KId test.cf | grep -A1 "Received line from module\: 'log_"
   debug: Received line from module: 'log_info=Cloning 'https://github.com/cfengine/masterfiles' -> '/opt/cfengine/masterfiles'...'
    info: Cloning 'https://github.com/cfengine/masterfiles' -> '/opt/cfengine/masterfiles'...
   debug: Received line from module: 'log_info=Successfully cloned 'https://github.com/cfengine/masterfiles' -> '/opt/cfengine/masterfiles''
    info: Successfully cloned 'https://github.com/cfengine/masterfiles' -> '/opt/cfengine/masterfiles'

Only the lines following a log_ line:

$ rm -rf /opt/cfengine/ && /var/cfengine/bin/cf-agent -KId test.cf | grep -A1 "Received line from module\: 'log_" | grep --invert-match "Received line from module"
    info: Cloning 'https://github.com/cfengine/masterfiles' -> '/opt/cfengine/masterfiles'...
    info: Successfully cloned 'https://github.com/cfengine/masterfiles' -> '/opt/cfengine/masterfiles'

Only lines received from module:

$ /var/cfengine/bin/cf-agent -KId test.cf | grep "Received line from module"
   debug: Received line from module: '{"operation": "validate_promise", "promiser": "/opt/cfengine/masterfiles", "attributes": {"repo": "https://github.com/cfengine/masterfiles"}, "result": "valid"}'
   debug: Received line from module: '{"operation": "evaluate_promise", "promiser": "/opt/cfengine/masterfiles", "attributes": {"repo": "https://github.com/cfengine/masterfiles"}, "result": "kept", "result_classes": ["/opt/cfengine/masterfiles_cloned_already"]}'
   debug: Received line from module: '{"operation": "terminate", "result": "success"}'
[...]

Exclude lines received from module:

$ /var/cfengine/bin/cf-agent -KId test.cf | grep --invert-match "Received line from module"
[...]
   debug: DeRefCopyPromise():     copying constraint: 'repo'
   debug: Received header from promise module: 'git_promise_module 0.0.2 v1 json_based'
   debug: Setting class: default:_opt_cfengine_masterfiles_cloned_already
 verbose: Additional promise info: source path 'test.cf' at line 10
[...]

Only debug messages:

$ /var/cfengine/bin/cf-agent -KId test.cf | grep "^   debug"
[...]
   debug: Setting class: default:_opt_cfengine_masterfiles_cloned_already
   debug: Received line from module: '{"operation": "terminate", "result": "success"}'
   debug: cf_pwait - waiting for process 28022
   debug: cf_pwait - process 28022 exited with code: 0
   debug: Updating package cache.
   debug: Hashed critical section lock 'CF_CRITICAL_SECTION' to 'CF_CRITICAL_SECTION'
   debug: Acquiring critical section lock 'CF_CRITICAL_SECTION'
   debug: Acquired critical section lock 'CF_CRITICAL_SECTION'
   debug: Releasing critical section lock 'CF_CRITICAL_SECTION'
   debug: Released critical section lock 'CF_CRITICAL_SECTION'
$

Only debug messages and excluding line received messages:

$ /var/cfengine/bin/cf-agent -KId test.cf | grep "^   debug" | grep --invert-match "Received line from module"
[...]
   debug: Setting class: default:_opt_cfengine_masterfiles_cloned_already
   debug: cf_pwait - waiting for process 28022
   debug: cf_pwait - process 28022 exited with code: 0
   debug: Updating package cache.
   debug: Hashed critical section lock 'CF_CRITICAL_SECTION' to 'CF_CRITICAL_SECTION'
   debug: Acquiring critical section lock 'CF_CRITICAL_SECTION'
   debug: Acquired critical section lock 'CF_CRITICAL_SECTION'
   debug: Releasing critical section lock 'CF_CRITICAL_SECTION'
   debug: Released critical section lock 'CF_CRITICAL_SECTION'
$

Feature requests

It can be a bit confusing when cfengine.py catches an unhandled exception, logging each line from the stack trace, line by line, twice.

I think we could change the python library to send the whole stack trace in one (JSON) log message, which would work around this specific case: https://tracker.mender.io/browse/CFE-3600

Sometimes I'm only interested in log messages from the custom promise module.

Created a ticket for this: https://tracker.mender.io/browse/CFE-3601

[larsewi]

Great answer @olehermanse . Thanks again ! 👏

[nickanderson]

Probably it won't help here, but I think that log-modules could possibly be useful trying to implement this.

[root@hub ]# cf-promises --log-modules=help
--log-modules accepts a comma separated list of one or more of the following:
    help
    all
    evalctx
    expand
    iterations
    parser
    vartable
    vars
    locks
    ps

[larsewi]

Thanks @nickanderson . Probably won't help here, as you say. But that is great to know as that can be quite usefull many other things.