Make sure both stdout and stderr are flushed before you return from the
http post on /run
— Carlos
On Sat, Oct 27, 2018 at 12:37 PM Michele Sciabarra <mich...@sciabarra.com>
wrote:
> Developing with the Go runtime I wrote (yes I am eating my own dog food!)
> I found an issue. Of course, I tried to track it but I cannot see the
> differences so I post here for help since I think it is related to the way
> OpenWhisk interact with runtimes.
>
> The bug can be easily demonstrated with a very simple "echo" action:
>
> ---
> package main
>
> import (
> "fmt"
> "log"
> )
>
> // Main is...
> func Main(args map[string]interface{}) map[string]interface{} {
> log.Println(args["name"].(string))
> fmt.Println(args["name"].(string))
> return args
> }
>
> ---
>
>
> If I deploy and invoke it twice I get the wrong log for the activations:
>
> $ wsk -i action invoke logbug.go -p name alpha -b | tail +2 | jq -r
> .activationId >go.id
> $ wsk -i activation logs $(cat go.id)
> 2018-10-27T16:18:15.62887961Z stdout: alpha
> $ wsk -i activation result $(cat go.id)
> {
> "name": "alpha"
> }
> $ wsk -i action invoke logbug.go -p name beta -b | tail +2 | jq -r
> .activationId >go.id
> $ wsk -i activation logs $(cat go.id)
> 2018-10-27T16:18:15.634172847Z stderr: 2018/10/27 16:18:15 alpha
> $ wsk -i activation result $(cat go.id)
> {
> "name": "beta"
> }
>
> As you can see the output is associated to the wrong action, the stderr of
> the first action is taken from the second action.
>
> For comparison, I tried with an equivalent javascript action:
>
> ----
> function main(args) {
> console.log(args.name)
> console.error(args.name)
> return args
> }
> ----
>
> This one works properly:
>
> $ wsk -i action invoke logbug.js -p name alpha -b | tail +2 | jq -r
> .activationId >js.id
> $ wsk -i activation logs $(cat js.id)
> 2018-10-27T16:25:37.089015311Z stdout: alpha
> 2018-10-27T16:25:37.08909633Z stderr: alpha
> $ wsk -i activation result $(cat js.id)
> {
> "name": "alpha"
> }
> $ wsk -i action invoke logbug.js -p name beta -b | tail +2 | jq -r
> .activationId >js.id
> $ wsk -i activation logs $(cat js.id)
> 2018-10-27T16:25:37.446571251Z stderr: beta
> 2018-10-27T16:25:37.446598483Z stdout: beta
> $ wsk -i activation result $(cat js.id)
> {
> "name": "beta"
> }
>
> I tried to track the bug launching the runtime locally and looking for
> differences in the output but unfortunately, it looks identical!
>
> Example with JS:
>
> $ docker run -p 8080:8080 openwhisk/nodejs6action >js_out 2>js_err &
> $ invoke init logbug.js
> {"OK":true}
> $ invoke run '{"name":"Mike"}'
> {"name":"Mike"}
> $ invoke run '{"name":"Miri"}'
> {"name":"Miri"}
>
> Output:
>
> $ cat js_out
> Mike
> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX
> Miri
> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX
>
> $ cat js_err
> Mike
> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX
> Miri
> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX
>
> Example with GO
>
> $ docker run -p 8080:8080 openwhisk/actionloop-golang-v1.11 >go_out
> 2>go_err &
> $ invoke init logbug.go
> {"ok":true}
>
> $ invoke run '{"name":"Mike"}'
> {"name":"Mike"}
>
> $ invoke run '{"name":"Miri"}'
> {"name":"Miri"}
>
> Output:
>
> $ cat go_out
> Mike
> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX
> Miri
> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX
>
> $ cat go_err
> cat go_err
> 2018/10/27 16:32:47 Mike
> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX
> 2018/10/27 16:32:48 Miri
> XXX_THE_END_OF_A_WHISK_ACTIVATION_XXX
>
> I do not see any difference in output, so I guess the problem is related
> to something else, like timing or similar issues.
>
> Any hint?
>
>
> --
> Michele Sciabarra
> mich...@sciabarra.com
>
