"wsk activation poll" should prefix log statements with activation ID

[l2fprod]

Having the activation ID in all log statements will make it easier when debugging an execution as one could sort the rows to group them by activation ID.

Currently everything is mixed up:

Activation: vision-analysis (48581ba45fac4119a5970250e3f0b0d7)
Activation: vision-analysis (e2e22077ad3945b48b612436fe0bb334)
Activation: vision-analysis (3b33904f79f448beb0c913856363a088)
2016-02-23T15:28:02.015099357Z stdout: [ 3666c679c084045f3ce8fd5366ee5a0d ] Processing image.jpg from document
2016-02-23T15:28:13.826113391Z stdout: [ 3666c679c084045f3ce8fd5366ee5a0d ] OK
2016-02-23T15:28:14.837651635Z stdout: [ 3666c679c084045f3ce8fd5366ee5a0d ] Processing image.jpg from document
2016-02-23T15:28:18.889271119Z stdout: [ 3666c679c084045f3ce8fd5366ee5a0d ] OK
2016-02-23T15:28:28.280158105Z stdout: [ 3666c679c084045f3ce8fd5366ee5a0d ] Processing image.jpg from document
2016-02-23T15:28:31.245863607Z stdout: [ 3666c679c084045f3ce8fd5366ee5a0d ] OK
2016-02-23T15:28:34.482853574Z stdout: [ 3666c679c084045f3ce8fd5366ee5a0d ] Processing image.jpg from document
2016-02-23T15:28:38.577133336Z stdout: [ 3666c679c084045f3ce8fd5366ee5a0d ] OK
Activation: vision-analysis (0fa2dd0bb55f4df3ba68a571da1a6d34)
2016-02-23T15:51:12.976504553Z stdout: [ cd79105c27b8a96a34c9487de5ae3674 ] Processing image.jpg from document
2016-02-23T15:51:17.293723081Z stdout: [ cd79105c27b8a96a34c9487de5ae3674 ] OK
Activation: vision-analysis (21526c4dd7564090a9095941fa1d546b)
2016-02-23T15:51:29.006188995Z stdout: [ 3dfe009246a5be3eed46b476f527f22f ] Processing image.jpg from document
2016-02-23T15:51:32.361084759Z stdout: [ 3dfe009246a5be3eed46b476f527f22f ] OK
Activation: vision-analysis (123fb4243552491b94b6fcf6a94be745)
2016-02-23T16:17:53.955350233Z stdout: [ 446a5e1a48171008b3faa34b3bd33d00 ] Processing image.jpg from document
2016-02-23T16:17:59.847872226Z stdout: [ 446a5e1a48171008b3faa34b3bd33d00 ] OK

Note that in this output, I have prefixed all my log statements with the id of the cloudant document I process - it helps.

[sjfink]

I don't see "everything is mixed up". I see all the logs for each activation id printed together in a group.

Am I missing something?

[rabbah]

The current output does not provide the text in brackets [ activationId ]. So it is harder to tell which logs are for which activation id by scanning each line. In the current implementation, the header only has the activation id. The log lines do not.

[sjfink]

I'm not sure I want to see a redundant [ activationId] to each line by default. As a human I find the current format easy to read, as the groups are visually obvious.

Is the intent of this request to ease machine parsing or human consumption?

[l2fprod]

note that the text in brackets was not the activation id but a cloudant document id - actions do not have access to the activation id AFAIK.

Take this other output, there are multiple activations running in parallel and in this output I had not yet instrumented my logs to add the document id between brackets:

Activation: fullanalysis (ad77dbc576dd48308dcd8780a8b95356)
Activation: fullanalysis (c06f2ffd1700454594adb7d8b2b06de4)
Activation: fullanalysis (c0e9b0d40d0549008e0ed16056404175)
Activation: fullanalysis (c951f305d1564ad795b9651bf467df65)
2016-02-16T07:54:31.999980675Z stdout: Document change detected for type image
2016-02-16T07:54:32.000423367Z stdout: Calling /fullanalysis
2016-02-16T07:54:32.00945539Z  stdout: OK
2016-02-16T07:54:32.113198997Z stdout: null
2016-02-16T07:54:32.113843174Z stdout: /fullanalysis [activation] { activationId: 'fccbb56a95114f2c841425a0af119e8f',
2016-02-16T07:54:32.113901846Z stdout: result: undefined }
2016-02-16T07:54:32.12253156Z  stdout: Document change detected for type image
2016-02-16T07:54:32.18497239Z  stdout: Document change detected for type image
2016-02-16T07:54:32.471340673Z stdout: Extracting image.jpg from document
Activation: fullanalysis (b6c55e104bbd4eafb0f5d7074375de8c)
Activation: fullanalysis (bc575aecd70b44c990704bc79355cda1)
Activation: fullanalysis (bce995309afa4475b5dc1ecaab32aa05)
2016-02-16T07:54:32.719576271Z stdout: Document change detected for type image
2016-02-16T07:54:32.941981163Z stdout: Document change detected for type image
2016-02-16T07:54:33.723276529Z stdout: Extracting image.jpg from document
2016-02-16T07:54:34.814087519Z stdout: Extracting image.jpg from document
2016-02-16T07:54:35.574138474Z stdout: Extracting image.jpg from document
2016-02-16T07:54:36.488183819Z stdout: OK
Activation: fullanalysis (c3178c31e6b84bf0bb6e6e3bccc14bd7)
Activation: fullanalysis (c775f460debf49cd892248dacf6729de)
2016-02-16T07:54:36.918917705Z stdout: Extracting image.jpg from document
2016-02-16T07:54:37.32104731Z  stdout: Extracting image.jpg from document
2016-02-16T07:54:38.44264612Z  stdout: Extracting image.jpg from document
2016-02-16T07:54:38.750746016Z stdout: stdout: Video thumbnail result { ok: true,
2016-02-16T07:54:38.750840344Z stdout: id: 'f1299c3f7627740de0988787e57514f9',
2016-02-16T07:54:38.750869059Z stdout: rev: '33-b8a00cf702a16a495b8f941be54cbbd7' }
2016-02-16T07:54:38.750892061Z stdout: 
2016-02-16T07:54:38.751216353Z stdout: stdout: Waterfall completed successfully
2016-02-16T07:54:38.751248836Z stdout: Removing temp directory
2016-02-16T07:54:38.751270671Z stdout: 
2016-02-16T07:54:38.818240644Z stdout: child process exited with code 0
2016-02-16T07:54:39.198959769Z stdout: Extracting image.jpg from document
2016-02-16T07:54:39.379458316Z stdout: OK
2016-02-16T07:54:39.732276564Z stdout: OK
2016-02-16T07:54:39.83616684Z  stdout: Extracting image.jpg from document
2016-02-16T07:54:40.141501033Z stdout: Extracting image.jpg from document
2016-02-16T07:54:40.597140042Z stdout: OK
2016-02-16T07:54:40.625787114Z stdout: OK
2016-02-16T07:54:40.689005776Z stdout: OK
2016-02-16T07:54:40.998410102Z stdout: Extracting image.jpg from document
2016-02-16T07:54:41.056300519Z stdout: Extracting image.jpg from document
2016-02-16T07:54:41.073502719Z stdout: Extracting image.jpg from document
2016-02-16T07:54:41.242269622Z stdout: Extracting image.jpg from document
2016-02-16T07:54:42.044496959Z stdout: Extracting image.jpg from document
2016-02-16T07:54:42.556204092Z stdout: OK
2016-02-16T07:54:42.723861667Z stdout: OK
2016-02-16T07:54:42.896531296Z stdout: Extracting image.jpg from document
2016-02-16T07:54:42.981171431Z stdout: Extracting image.jpg from document
2016-02-16T07:54:43.136827416Z stdout: Extracting image.jpg from document
2016-02-16T07:54:43.820393254Z stdout: OK
2016-02-16T07:54:44.245523171Z stdout: Extracting image.jpg from document
2016-02-16T07:54:44.737985791Z stdout: OK
2016-02-16T07:54:44.837519463Z stdout: OK
2016-02-16T07:54:44.885837036Z stdout: Extracting image.jpg from document
2016-02-16T07:54:45.037349421Z stdout: OK
2016-02-16T07:54:45.134481738Z stdout: OK
2016-02-16T07:54:45.242562757Z stdout: Extracting image.jpg from document
2016-02-16T07:54:45.676012878Z stdout: Extracting image.jpg from document
2016-02-16T07:54:46.312272503Z stdout: OK
2016-02-16T07:54:46.377719625Z stdout: OK
2016-02-16T07:54:48.861217253Z stdout: OK
2016-02-16T07:54:49.267126547Z stdout: Extracting image.jpg from document
2016-02-16T07:54:49.272499647Z stdout: OK
2016-02-16T07:54:49.275377413Z stdout: OK
2016-02-16T07:54:49.537882773Z stdout: OK
2016-02-16T07:54:49.673050565Z stdout: Extracting image.jpg from document
2016-02-16T07:54:49.843400254Z stdout: Extracting image.jpg from document
2016-02-16T07:54:49.969509296Z stdout: OK
2016-02-16T07:54:50.204488311Z stdout: OK
2016-02-16T07:54:50.551998489Z stdout: OK

I don't think the groups are obvious.

Today if something goes wrong in one activation, "wsk activation list" does not give me any clue about which activations failed neither how to link it to a specific document id. I would have to look at the individual activations - and there could be a lot.

So my best tool today is "wsk activation poll" with the "since" parameter to retrieve the last hours/days, find a trace with my document id and try to identify the activation id from there.

[rabbah]

@l2fprod In your instrumented logs, the id between brackets is an id that is meaningful to you (it is from your action), not an activation id. @sjfink's point is that the log messages in the poll output already demarcates the log activations and prefixing every log message with that id is redundant.

I like your suggesting of reporting a better summary in activation list: status (success or failure), and maybe activation duration (discussed in #20).

[l2fprod]

so I missed something in how "activation poll" works. It does not work like "tail" showing all the logs from all activations as they happen. Rather it logs an activation ID and its logs when it completes. and in this case there is proper grouping.

What is weird is that in the output I pasted this is not happening and you can see several "Activation: name (id)" lines without logs in between and I think I found why:

Consider this badly written action where the calls to whisk.done/async are commented

function main(args) {
  var sleepFor = Math.random() * 5000;
  //console.log("Sleeping for", sleepFor);
  setTimeout(function () {
    console.log("done!");
    //whisk.done(undefined, null);
  }, sleepFor);
  //return whisk.async();
}

create the action

wsk action create bad badaction.js

enable the poll

wsk activation poll

submit a bunch of them

for i in `seq 1 10`; do wsk action invoke bad& done

this is the output I got:

Activation: bad (c075e249d7a345b2b0dbfeed02f74b85)
2016-03-01T14:37:18.006337633Z stdout: done!
2016-03-01T14:37:18.217177728Z stdout: done!
Activation: bad (e2651fa6418b4eefac2ceb13dcf95f65)
Activation: bad (8ce77bbe3b924e8fa1c16f8013205a2f)
Activation: bad (b18975147da54e33beaab2dbefb86b6d)
Activation: bad (aa12e7be019a4e43803d207c3bc4daa4)
Activation: bad (ef44bf7df80b47658b832180b902dd5d)
Activation: bad (52a66d13771d49d4950b51b401b6ef13)
Activation: bad (318ac51e01a04c5ebaf732707e71422c)
2016-03-01T14:37:19.159226693Z stdout: done!
Activation: bad (29857d67deec4d9d829b5d5dff0c2123)
Activation: bad (7fea504493ea4ecca581edc2a55c777e)

now if I send some more:

Activation: bad (a4edaa3a08634e24b245099856d60cd8)
2016-03-01T14:38:48.656056548Z stdout: done!
2016-03-01T14:38:48.656137681Z stdout: done!
2016-03-01T14:38:48.656232864Z stdout: done!
2016-03-01T14:38:48.656302012Z stdout: done!
2016-03-01T14:38:48.656391177Z stdout: done!
2016-03-01T14:38:48.656984195Z stdout: done!

and I think that is what happened in the logs I put at the beginning of this ticket. I was not correctly calling whisk.async/done/error and this seems to have an impact on the logging output.

[sjfink]

Yes, this is exactly as I would expect. Since you did not return whisk.async(), technically the activation ended at the return statement, and the asynchronous log was attributed to the next activation. This is by design and is a feature and not a bug.

Now that we agree that logs are not interleaved for correct actions, but grouped as intended, do you still think we should have the activation id on each line?

[l2fprod]

Provided the developer correctly calls whisk.async/done, the grouping works the purpose - no need for the activation id.

However the fact that logs done in the context of one activation gets attached to the next activation because I did not call whisk.async() looks like an unexpected side-effect. Now I have an activation record that has captured the execution logs of multiple action invocations. This sounds like a bug.

[sjfink]

The programming model specifies that if you leave background processing running when you finish an activation, the activity will be charged to the next activation, if there's an activation in the same container. This is pretty fundamental -- in any case it is certainly a feature and not a bug.

Apart from that, it appears that we agree that grouping works the purpose and there's no need to print the activation id on each line. So closing as "won't fix".

[mbehrendt]

@sjfink i tend to agree that from a user perspective, this behavior might be perceived as causing undesired side-effects / inconsistent behavior. eg would the 'charging to the next activation' only be done if the same container gets hit? eg would there be no charging if a different container gets hit? might cause the user to be puzzled on why charging is sometimes done and in other cases not.

a more consistent behavior would in my mind be if the container was terminated after a defined timeout window -- or, if the user ends up being in the happy position that his process continued running in the background since the container was cached, then there wouldn't be any charging for the period of time while the container was in the cache.

[sjfink]

@mbehrendt note that no container will run at all in the background -- "idle" containers are paused, no matter whether the user tries to spawn a background process or not. The user will never see charges for any activity except for the normal "synchronous" activation lifetime. The user is never charged while the container is idle in a cache.

[mbehrendt]

@sjfink i was referring to this stmt from you: " if you leave background processing running when you finish an activation, the activity will be charged to the next activation, if there's an activation in the same container."

this sounds to me like the user is charged on the next activation based on a running background process. if not, what is the right way of interpreting this?

[sjfink]

Well, the user is being charged on the next activation based on the time spent in the next activation. It's true that a runaway background process will also be running, and that might slow down the work during the next activation -- but it's an indirect effect -- the user will not be charged directly for the runaway background activity.

[mbehrendt]

thank you, that now makes sense to me. however, this part of your stmt is still unclear to me and i'm struggling to understand how it fits with your last comment: "the activity will be charged to the next activation, if there's an activation in the same container." . what do you mean by that?