We could add a test for every runtime in the core repo integration tests,
similar way we have the tests for Unicode.
On Sun, Oct 28, 2018 at 10:13 AM Carlos Santana <csantan...@gmail.com>
wrote:
> 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
> >>>
>
