You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@openwhisk.apache.org by Michele Sciabarra <mi...@sciabarra.com> on 2018/10/27 16:36:58 UTC
[long] I need help to find an issue with the Go runtime that I cannot
track down
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
Re: [long] I need help to find an issue with the Go runtime that I
cannot track down
Posted by Michele Sciabarra <mi...@sciabarra.com>.
See my example test below, invoke an action that outputs on stdout AND stderr, get the activation id and retrieve the result. Twice is better.
The bug does not show up when you send only one line of log, it was triggered by at least 2 (one in stdout and another in stderr). Invoke twice to detect the "out-of-band" behavior. I did some simple tests with just one line of output of log and it worked.
I sorted out fist ensuring I flush the logs BEFORE completing the request, but it was not enough, I also had to use bufio.Flush. No idea why this works and os.Stdout.Sync() does not, even the recommended way in the Go documentation for flushing IO is to wrap the stdout in an bufio.Writer then flush it.
--
Michele Sciabarra
michele@sciabarra.com
----- Original message -----
From: Carlos Santana <cs...@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: Sun, 28 Oct 2018 10:13:31 -0400
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 <ro...@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 <mi...@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 <cs...@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 <mi...@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
>>>
Re: [long] I need help to find an issue with the Go runtime that I
cannot track down
Posted by Carlos Santana <cs...@gmail.com>.
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 <cs...@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 <ro...@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 <mi...@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 <cs...@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
> >>>
>
Re: [long] I need help to find an issue with the Go runtime that I cannot track down
Posted by Carlos Santana <cs...@gmail.com>.
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 <ro...@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 <mi...@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 <cs...@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 <mi...@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
>>>
Re: [long] I need help to find an issue with the Go runtime that I cannot track down
Posted by Rodric Rabbah <ro...@gmail.com>.
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 <mi...@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 <cs...@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 <mi...@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
>>
Re: [long] I need help to find an issue with the Go runtime that I
cannot track down
Posted by Michele Sciabarra <mi...@sciabarra.com>.
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 <cs...@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 <mi...@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
>
Re: [long] I need help to find an issue with the Go runtime that I
cannot track down
Posted by Carlos Santana <cs...@gmail.com>.
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 <mi...@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
>