Add connection test for kuiper

[MonicaisHer]

• test Kuiper 1.4.2 new feature, re-use edgex message bus as sink's action
• update rules' format and naming, to improve error logs

Test guideline

1. build edgexfoundry snap with kuiper version 1.4.2

   git clone https://github.com/MonicaisHer/edgex-go.git
   cd edgex-go
   git checkout EDGEX-172-update-kuiper-to-1-4-x
   snapcraft

2. test kuiper with local edgexfoundry snap

   cd edgex-checkbox-provider/data/latest
   sudo ./run-all-tests-locally.sh -t test-rules-engine.sh -s <.../edgex-go/edgexfoundry_2.0.1-dev.71_amd64.snap> -v

   Expect:

   running single test: test-rules-engine.sh ...   PASSED
   snap "edgexfoundry" is not installed
   edgexfoundry 2.0.1-dev.71 installed
   waiting for all services to come online. Current retry count: 1/300
   waiting for all services to come online. Current retry count: 2/300
   waiting for all services to come online. Current retry count: 3/300
   all services up
   waiting for device-virtual produce readings, current retry count: 1/60
   waiting for device-virtual produce readings, current retry count: 2/60
   waiting for device-virtual produce readings, current retry count: 3/60
   waiting for device-virtual produce readings, current retry count: 4/60
   waiting for device-virtual produce readings, current retry count: 5/60
   waiting for device-virtual produce readings, current retry count: 6/60
   waiting for device-virtual produce readings, current retry count: 7/60
   waiting for device-virtual produce readings, current retry count: 8/60
   waiting for device-virtual produce readings, current retry count: 9/60
   waiting for device-virtual produce readings, current retry count: 10/60
   waiting for device-virtual produce readings, current retry count: 11/60
   device-virtual is producing readings now
   check port 59720 status open services timed out, current retry count: 1/300
   time="2022-01-25 15:12:02" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:02" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:03" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:03" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:03" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:03" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:03" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   waiting for readings come into stream, current retry count: 1/60
   time="2022-01-25 15:12:04" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   readings come into stream now
   time="2022-01-25 15:12:04" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:04" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:04" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:04" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:05" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:05" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:05" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:05" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   time="2022-01-25 15:12:05" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
   edgexfoundry removed

[MonicaisHer]

This test is still not stable in my machine, it has about 50% chance to pass, and each time the error messages are different, for example:

• cannot stop rule Connecting to 127.0.0.1:20498... Failed to connect the server, please start the server.
• waiting for all services to come online. Current retry count: 300/300 services timed out, reached max retry count of 300
• cannot stop rule Connecting to 127.0.0.1:20498... Rule rule_log was not found.
• waiting for device-virtual produce readings, reached maximum retry count of 60
• Connecting to 127.0.0.1:20498... Stopped: redis: can't parse "VR5cGUiOiJVaW50MTYiLCJ2YWx1ZSI6IjIyNDAzIn1dfQ==\",\"ContentType\":\"application/json\"}".
• Connecting to 127.0.0.1:20498... Stopped: redis: can't parse "json\"}".

[farshidtz]

Error 1

time="2022-01-25 18:33:48" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
cannot stop rule

This appears in the logs at the same time:

Jan 26 09:56:42 farshid-cirrus7 edgexfoundry.kuiper[54862]: time="2022-01-26 09:56:42" level=error msg="closing rule rule_mqtt for error: redis: can't parse \"iI4Njg2Mjk3OTU4ODExOTIyODQwIn1dfQ==\\\",\\\"ContentType\\\":\\\"application/json\\\"}\"" file="server/ruleManager.go:114"

Error 2

time="2022-01-26 09:54:37" level=info msg="Specified Kuiper base folder at location /var/snap/edgexfoundry/x1/kuiper.\n" file="conf/path.go:100"
cannot run rule's action: rule_edgex_message_bus

Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: redis: 2022/01/26 09:54:37 pubsub.go:160: redis: discarding bad PubSub connection: redis: can't parse "ion/json\"}"
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: panic: runtime error: slice bounds out of range [1538:769]
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: goroutine 121 [running]:
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: bufio.(*Reader).ReadSlice(0xc000444c60, 0xb0)
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         bufio/bufio.go:335 +0x225
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/go-redis/redis/v7/internal/proto.(*Reader).readLine(0x0)
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/go-redis/redis/v7@v7.3.0/internal/proto/reader.go:72 +0x25
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/go-redis/redis/v7/internal/proto.(*Reader).ReadLine(0x0)
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/go-redis/redis/v7@v7.3.0/internal/proto/reader.go:58 +0x19
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/go-redis/redis/v7/internal/proto.(*Reader).ReadReply(0xc07460f359d77f0e, 0x14ea598)
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/go-redis/redis/v7@v7.3.0/internal/proto/reader.go:84 +0x2a
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/go-redis/redis/v7.(*Cmd).readReply(...)
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/go-redis/redis/v7@v7.3.0/command.go:276
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/go-redis/redis/v7.(*PubSub).ReceiveTimeout.func1(0xc000240108)
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/go-redis/redis/v7@v7.3.0/pubsub.go:356 +0x31
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/go-redis/redis/v7/internal/pool.(*Conn).WithReader(0xc0000ac4b0, {0x160bba8, 0xc0000360b8}, 0xc000302e98, 0xc000302ea8)
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/go-redis/redis/v7@v7.3.0/internal/pool/conn.go:65 +0x6d
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/go-redis/redis/v7.(*PubSub).ReceiveTimeout(0xc000331c00, 0x0)
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/go-redis/redis/v7@v7.3.0/pubsub.go:355 +0xad
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/go-redis/redis/v7.(*PubSub).Receive(...)
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/go-redis/redis/v7@v7.3.0/pubsub.go:371
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/go-redis/redis/v7.(*PubSub).ReceiveMessage(0xc00000e510)
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/go-redis/redis/v7@v7.3.0/pubsub.go:379 +0x2c
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/edgexfoundry/go-mod-messaging/v2/internal/pkg/redis.(*goRedisWrapper).Receive(0xc000386020, {0xc000438410, 0x0})
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/edgexfoundry/go-mod-messaging/v2@v2.1.0/internal/pkg/redis/goredis.go:78 +0x2a
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: github.com/edgexfoundry/go-mod-messaging/v2/internal/pkg/redis.Client.Subscribe.func1()
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/edgexfoundry/go-mod-messaging/v2@v2.1.0/internal/pkg/redis/client.go:142 +0x70
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]: created by github.com/edgexfoundry/go-mod-messaging/v2/internal/pkg/redis.Client.Subscribe
Jan 26 09:54:37 farshid-cirrus7 edgexfoundry.kuiper[48575]:         github.com/edgexfoundry/go-mod-messaging/v2@v2.1.0/internal/pkg/redis/client.go:140 +0x1c5

[farshidtz]

I've created a potential fix to a clear bug: https://github.com/farshidtz/go-mod-messaging/commit/823a44fdf5e24b7020773ba337bddadfa024dc24

That's a dependency of kuiper and you'd need to replace it at https://github.com/lf-edge/ekuiper/blob/95e8b5776023d3f54e9a3016e52762b12f7e5b03/go.mod#L11

Suggested way to test:

1. fork kuiper
2. replace Line 11 of go.mod with something like github.com/farshidtz/go-mod-messaging@823a44f and check that in.
3. change kuiper source in snapcraft.yaml to point to your fork/branch

Update: this bugfix doesn't solve the kuiper errors. Kuiper uses a single channel/topic per subscription and not affected by this bug.

[farshidtz]

@MonicaisHer good catch. We need to document the current need for setting SHARED="true" and report the errors which would result from not doing so as a bug.

@tonyespy do you have some other insights?

[MonicaisHer]

Vault’s failure->security-secretstore-setup->security-bootstrapper-redis->device-virtual Vault’s failure->security-secretstore-setup->security-consul-bootstrapper->app-service-configurable

Error logs:

• msg="unable to make request to health check failed: Get \"http://localhost:8200/v1/sys/health\": dial tcp 127.0.0.1:8200: connect: connection refused"
• msg="vault is in an unknown state. No Status code available" Full logs: https://pastebin.canonical.com/p/dvKcvWmpRJ/

The probable reason for getting the connection refused is that the Vault Server is not up and running.

[MonicaisHer]

With SHARED=false, this bug will eventually cause errors, and errors will appear later when rules run as expected for a while. For example:

rule_log: Running(working) ->(few minutes later) -> Stopped: redis: can't parse "\"}".
rule_mqtt: Running(working) ->(few minutes later) -> Stopped: read tcp 127.0.0.1:53254->127.0.0.1:6379: use of closed network connection.