Great Michele +1
Rodric,
I was thinking the same, on how to catch this on the conformance unit tests.
I think running 2 invokes would catch this since the unit test framework to do
the docker run doesn’t do reuse.
I think to reproduce needs to be done with a fast back to back invokes but
using the same container.
- Carlos Santana
@csantanapr
> On Oct 28, 2018, at 8:32 AM, Rodric Rabbah <rod...@gmail.com> wrote:
>
> 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
>>>
