openwhisk-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Carlos Santana <csantan...@gmail.com>
Subject Re: [long] I need help to find an issue with the Go runtime that I cannot track down
Date Sat, 27 Oct 2018 18:38:18 GMT
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 <michele@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
>   michele@sciabarra.com
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message