openwhisk-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Rodric Rabbah <rod...@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 12:32:55 GMT
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