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
[email protected]
