I’m wondering why the “basic” runtime unit tests didn’t catch the lack of flush
(this same symptom was observed during the dev of C# runtime and I thought the
unit tests flagged it). Maybe we need a tighter tests with two invokes.
-r
> On Oct 28, 2018, at 7:47 AM, Michele Sciabarra <mich...@sciabarra.com> wrote:
>
> Ok I fixed it.
> Please merge PR58
>
> If someone could explain me why os.File.Sync() is not enough to flush the
> stdout/stderr, and you need to wrap stdout/stderr in bufio.Writer and Flush()
> it, I would be happy.
>
> --
> Michele Sciabarra
> mich...@sciabarra.com
>
> ----- Original message -----
> From: Carlos Santana <csantan...@gmail.com>
> To: dev@openwhisk.apache.org
> Subject: Re: [long] I need help to find an issue with the Go runtime that I
> cannot track down
> Date: Sat, 27 Oct 2018 14:38:18 -0400
>
> 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
>>
