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 Sun, 28 Oct 2018 14:13:31 GMT
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 <rodric@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 <michele@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
>> michele@sciabarra.com
>> 
>> ----- Original message -----
>> From: Carlos Santana <csantana23@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 <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
View raw message