openwhisk-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Michele Sciabarra <mich...@sciabarra.com>
Subject [long] I need help to find an issue with the Go runtime that I cannot track down
Date Sat, 27 Oct 2018 16:36:58 GMT
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