Failing test: TestKVWithEmptyValue with master go on ppc64le

[Rajalakshmi-Girish]

Following Error for TestKVWithEmptyValue:

--- FAIL: TestKVWithEmptyValue (0.12s)
    logger.go:130: 2021-04-22T02:16:41.750Z     INFO    m0      LISTEN GRPC     {"member": "m0", "m.grpcAddr": "localhost:m0", "m.Name": "m0"}
    logger.go:130: 2021-04-22T02:16:41.751Z     INFO    m0      launching a member      {"member": "m0", "name": "m0", "advertise-peer-urls": ["unix://127.0.0.1:215174179541"], "listen-client-urls": ["unix://127.0.0.1:215184179541"], "grpc-address": "unix://localhost:m00"}
    logger.go:130: 2021-04-22T02:16:41.752Z     INFO    m0      opened backend db       {"member": "m0", "path": "/tmp/TestKVWithEmptyValue3985847728/002/etcd4041780374/member/snap/db", "took": "1.166028ms"}
    logger.go:130: 2021-04-22T02:16:41.753Z     INFO    m0      starting local member   {"member": "m0", "local-member-id": "fa19bbaf425c7e1c", "cluster-id": "5ed47e72b9de8e47"}
    logger.go:130: 2021-04-22T02:16:41.753Z     INFO    m0.raft fa19bbaf425c7e1c switched to configuration voters=()    {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.753Z     INFO    m0.raft fa19bbaf425c7e1c became follower at term 0      {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.753Z     INFO    m0.raft newRaft fa19bbaf425c7e1c [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0] {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.753Z     INFO    m0.raft fa19bbaf425c7e1c became follower at term 1      {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.753Z     INFO    m0.raft fa19bbaf425c7e1c switched to configuration voters=(18021641745306779164)        {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.754Z     WARN    m0      simple token is not cryptographically signed    {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.756Z     INFO    m0      starting etcd server    {"member": "m0", "local-member-id": "fa19bbaf425c7e1c", "local-server-version": "3.5.0-alpha.0", "cluster-version": "to_be_decided"}
    logger.go:130: 2021-04-22T02:16:41.757Z     INFO    m0      started as single-node; fast-forwarding election ticks  {"member": "m0", "local-member-id": "fa19bbaf425c7e1c", "forward-ticks": 9, "forward-duration": "90ms", "election-ticks": 10, "election-timeout": "100ms"}
    logger.go:130: 2021-04-22T02:16:41.757Z     INFO    m0.raft fa19bbaf425c7e1c switched to configuration voters=(18021641745306779164)        {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.757Z     INFO    m0      added member    {"member": "m0", "cluster-id": "5ed47e72b9de8e47", "local-member-id": "fa19bbaf425c7e1c", "added-peer-id": "fa19bbaf425c7e1c", "added-peer-peer-urls": ["unix://127.0.0.1:215174179541"]}
logger.go:130: 2021-04-22T02:16:41.758Z     INFO    m0      launched a member       {"member": "m0", "name": "m0", "advertise-peer-urls": ["unix://127.0.0.1:215174179541"], "listen-client-urls": ["unix://127.0.0.1:215184179541"], "grpc-address": "unix://localhost:m00"}
    logger.go:130: 2021-04-22T02:16:41.854Z     INFO    m0.raft fa19bbaf425c7e1c is starting a new election at term 1   {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.854Z     INFO    m0.raft fa19bbaf425c7e1c became candidate at term 2     {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.854Z     INFO    m0.raft fa19bbaf425c7e1c received MsgVoteResp from fa19bbaf425c7e1c at term 2   {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.854Z     INFO    m0.raft fa19bbaf425c7e1c became leader at term 2        {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.854Z     INFO    m0.raft raft.node: fa19bbaf425c7e1c elected leader fa19bbaf425c7e1c at term 2   {"member": "m0"}
    logger.go:130: 2021-04-22T02:16:41.854Z     INFO    m0      published local member to cluster through raft  {"member": "m0", "local-member-id": "fa19bbaf425c7e1c", "local-member-attributes": "{Name:m0 ClientURLs:[unix://127.0.0.1:215184179541]}", "request-path": "/0/members/fa19bbaf425c7e1c/attributes", "cluster-id": "5ed47e72b9de8e47", "publish-timeout": "5.2s"}
    logger.go:130: 2021-04-22T02:16:41.854Z     INFO    m0      setting up initial cluster version      {"member": "m0", "cluster-version": "3.5"}
    logger.go:130: 2021-04-22T02:16:41.854Z     INFO    m0      set initial cluster version     {"member": "m0", "cluster-id": "5ed47e72b9de8e47", "local-member-id": "fa19bbaf425c7e1c", "cluster-version": "3.5"}
    logger.go:130: 2021-04-22T02:16:41.854Z     INFO    m0      cluster version is updated      {"member": "m0", "cluster-version": "3.5"}
    cluster.go:251:  - m0 -> fa19bbaf425c7e1c (unix://localhost:m00)
    logger.go:130: 2021-04-22T02:16:41.858Z     INFO    grpc    [[core] parsed scheme: "etcd-endpoints"]
    logger.go:130: 2021-04-22T02:16:41.858Z     INFO    grpc    [[core] ccResolverWrapper: sending update to cc: {[{unix:localhost:m00 localhost <nil> 0 <nil>}] 0xc00adc6ba0 <nil>}]
    logger.go:130: 2021-04-22T02:16:41.858Z     INFO    grpc    [[core] ClientConn switching balancer to "round_robin"]
    logger.go:130: 2021-04-22T02:16:41.858Z     INFO    grpc    [[core] Channel switches to new LB policy "round_robin"]
    logger.go:130: 2021-04-22T02:16:41.858Z     INFO    grpc    [[balancer] base.baseBalancer: got new ClientConn state:  {{[{unix:localhost:m00 localhost <nil> 0 <nil>}] 0xc00adc6ba0 <nil>} <nil>}]
    logger.go:130: 2021-04-22T02:16:41.858Z     INFO    grpc    [[core] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2021-04-22T02:16:41.858Z     INFO    grpc    [[core] Subchannel picks a new address "unix:localhost:m00" to connect]
    logger.go:130: 2021-04-22T02:16:41.858Z     INFO    grpc    [[balancer] base.baseBalancer: handle SubConn state change: 0xc0137e3ab0, CONNECTING]
    logger.go:130: 2021-04-22T02:16:41.858Z     INFO    grpc    [[core] Channel Connectivity change to CONNECTING]
    logger.go:130: 2021-04-22T02:16:41.861Z     INFO    grpc    [[core] Subchannel Connectivity change to READY]
    logger.go:130: 2021-04-22T02:16:41.861Z     INFO    grpc    [[balancer] base.baseBalancer: handle SubConn state change: 0xc0137e3ab0, READY]
    logger.go:130: 2021-04-22T02:16:41.861Z     INFO    grpc    [[roundrobin] roundrobinPicker: newPicker called with info: {map[0xc0137e3ab0:{{unix:localhost:m00 localhost <nil> 0 <nil>}}]}]
    logger.go:130: 2021-04-22T02:16:41.861Z     INFO    grpc    [[core] Channel Connectivity change to READY]
    v3_kv_test.go:39: my-namespace/foobar = data
    v3_kv_test.go:39: my-namespace/foobar1 = data
    v3_kv_test.go:39: namespace/foobar1 = data
    v3_kv_test.go:46: etcdserver: key is not provided
    logger.go:130: 2021-04-22T02:16:41.865Z     INFO    grpc    [[core] Channel Connectivity change to SHUTDOWN]
    logger.go:130: 2021-04-22T02:16:41.865Z     INFO    grpc    [[core] Subchannel Connectivity change to SHUTDOWN]
    logger.go:130: 2021-04-22T02:16:41.865Z     INFO    m0      terminating a member    {"member": "m0", "name": "m0", "advertise-peer-urls": ["unix://127.0.0.1:215174179541"], "listen-client-urls": ["unix://127.0.0.1:215184179541"], "grpc-address": "unix://localhost:m00"}
    logger.go:130: 2021-04-22T02:16:41.865Z     INFO    grpc    [[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2021-04-22T02:16:41.865Z     INFO    grpc    [[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]

Environment

go version devel go1.17-5daefc5363 Thu Apr 22 01:40:02 2021 +0000 linux/ppc64le
Linux ppc64le

Reproduce

go test go.etcd.io/etcd/tests/v3/integration
Ran integration tests of etcd-io/etcd

What did you expect to see?

Should Pass successfully.
NOTE: It passed with the stable release of go.

[root@rajalakshmi1-workspace etcd]# go test go.etcd.io/etcd/tests/v3/integration

ok      go.etcd.io/etcd/tests/v3/integration    191.044s
[root@rajalakshmi1-workspace etcd]# go version
go version go1.16 linux/ppc64le
[root@rajalakshmi1-workspace etcd]

Reference

golang/go#45685

Please find the attached log
etcd.log

[lilic]

Thank you for your report! Since we are only using 1.16 for now, but should be important when we switch to 1.17.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 21 days if no further activity occurs. Thank you for your contributions.

[Rajalakshmi-Girish]

We saw this failure in our CI job last on 2021-08-12 20:07:01 +0000 UTC. Please see if you can access https://prow.ppc64le-cloud.org/view/s3/prow-logs/logs/postsubmit-master-golang-etcd-build-test-ppc64le/1425911681996820480

After the above Job, we started seeing unit test failures that exited the test run, and hence integration tests did not run.
I suspect this TestKVWithEmptyValue test failure to still exist.
@lilic can you please share if there is any further update on this test failure?

[tsaarni]

xref #13334

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 21 days if no further activity occurs. Thank you for your contributions.