"TestKVWithEmptyValue" of etcd-io/etcd fails with master go #45685

Rajalakshmi-Girish · 2021-04-22T02:52:39Z

What version of Go are you using (`go version`)?

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

Does this issue reproduce with the latest release?

No

What operating system and processor architecture are you using (`go env`)?

Linux ppc64le

What did you do?

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.

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

What did you see instead?

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"]

Please find the attached log
etcd.log

The text was updated successfully, but these errors were encountered:

Rajalakshmi-Girish · 2021-04-22T09:57:27Z

@laboger Can you please give some pointers?

laboger · 2021-04-23T13:12:05Z

@Rajalakshmi-Girish Can you provide directions on building etcd? Also information on when this last passed.

@pmur

pmur · 2021-04-23T15:54:40Z

Bisecting this failure, it started with 9a555fc

pmur · 2021-04-23T15:56:43Z

Note, I applied the fix from b98ce3b to avoid another failure masking this bug.

pmur · 2021-04-23T16:13:01Z

This also fails with

go version devel go1.17-d4bfe00615 Fri Apr 23 14:06:54 2021 +0000 linux/amd64

and etcd commit 9a3aff6d8fa2cdfafdfaac918c1ace7be65d11e5

cherrymui · 2021-04-26T17:31:22Z

Could you provide more information about why this is a Go bug, instead of a bug of etcd? Thanks.

Rajalakshmi-Girish · 2021-04-27T19:09:41Z

Could you provide more information about why this is a Go bug, instead of a bug of etcd? Thanks.

I thought so because it passed with stable go version and not with the master go.

Rajalakshmi-Girish · 2021-04-27T19:15:07Z

@Rajalakshmi-Girish Can you provide directions on building etcd? Also information on when this last passed.

@pmur

We built it using https://github.com/etcd-io/etcd/blob/master/build.sh
Do you still need the information on when it last passed? I see #45685 (comment)

cherrymui · 2021-04-27T19:15:42Z

I thought so because it passed with stable go version and not with the master go.

That doesn't imply it is a Go bug. The code might depend on buggy or internal behavior of earlier versions of Go, which may change.

laboger · 2021-05-07T21:54:43Z

Bisecting this failure, it started with 9a555fc

Hi Cherry, Paul narrowed this down to this commit.

Note, I applied the fix from b98ce3b to avoid another failure masking this bug.

This test also failed due to the bug that was later fix by this commit, so he had to backport that to avoid the error it fixes in both cases:
a61524d cmd/internal/obj: add Prog.SetFrom3{Reg,Const} This one works
9a555fc cmd/compile: fix missing descend in Addrtaken for closures. This one gets the same error identified in this issue.

So I think that it is likely to be a Golang issue due to that commit.
In the log that fails you get this error: v3_kv_test.go:48: etcdserver: key is not provided
If you run with etcd built with the good version and add the -v option, the correct log does not display this line.

There are multiple layers of closures as it tries to get the key.

@Rajalakshmi-Girish told me that there were also some failures on x86 when building and testing etcd with Go master that didn't happen in Go 1.16, but not exactly the same.

cherrymui · 2021-05-07T22:02:23Z

That commit enables inlining functions that include closures, which may result in changes of PCs if the test compares function PCs. Comparing function PCs are never supposed to work, as commented in #45697 (comment) . If the test indeed compares function PCs, that Go commit is working as intended and the test needs to be adjusted. Thanks.

laboger · 2021-05-14T21:55:57Z

Here is the function from etcd/client/v3/utils.go that is returning a different value than it was before, which causes the test to fail starting at the commit noted earlier in this issue:

func isOpFuncCalled(op string, opts []OpOption) bool {
        for _, opt := range opts {
                v := reflect.ValueOf(opt)
                if v.Kind() == reflect.Func {
                        if opFunc := runtime.FuncForPC(v.Pointer()); opFunc != nil {
                                if strings.Contains(opFunc.Name(), op) {
                                        return true
                                }
                        }
                }
        }
        return false
}

This is not exactly comparing function PCs, but it seems like this is something that might get different results if the function was inlined because then the FuncForPC would not be the same depending on whether it was inlined or not. If you agree, then @Rajalakshmi-Girish can open an issue for etcd and we can close this.

A related question: if comparing function PCs is not supposed to work, isn't that something the compiler should flag as incorrect syntax?

randall77 · 2021-05-14T22:11:41Z

A related question: if comparing function PCs is not supposed to work, isn't that something the compiler should flag as incorrect syntax?

Would be nice if we could. I'm not sure how you would do that. You'd have to know that a reflect.Value was made from a function, and then dataflow from Pointer results to see if they were used in comparisons (against things other than 0).

cherrymui · 2021-05-14T22:47:07Z

This is not exactly comparing function PCs, but it seems like this is something that might get different results if the function was inlined because then the FuncForPC would not be the same depending on whether it was inlined or not.

I agree this is not exactly comparing function PCs. But comparing function names is no better, especially for non-top-level functions. The naming scheme of closures is not documented, may vary in different toolchains, and subject to change (even without inlining). (Comparing names of top-level functions seems reasonable.)

Rajalakshmi-Girish · 2021-05-18T00:44:20Z

Here is the function from etcd/client/v3/utils.go that is returning a different value than it was before, which causes the test to fail starting at the commit noted earlier in this issue:
func isOpFuncCalled(op string, opts []OpOption) bool {
        for _, opt := range opts {
                v := reflect.ValueOf(opt)
                if v.Kind() == reflect.Func {
                        if opFunc := runtime.FuncForPC(v.Pointer()); opFunc != nil {
                                if strings.Contains(opFunc.Name(), op) {
                                        return true
                                }
                        }
                }
        }
        return false
}
This is not exactly comparing function PCs, but it seems like this is something that might get different results if the function was inlined because then the FuncForPC would not be the same depending on whether it was inlined or not. If you agree, then @Rajalakshmi-Girish can open an issue for etcd and we can close this.

A related question: if comparing function PCs is not supposed to work, isn't that something the compiler should flag as incorrect syntax?

@laboger I have raised an issue for etcd etcd-io/etcd#12993
Thank you.

cherrymui · 2021-05-18T14:43:56Z

A related question: if comparing function PCs is not supposed to work, isn't that something the compiler should flag as incorrect syntax?

It is already a compile-time error for comparing func values (except comparing with nil). But this code uses reflection, so everything is dynamic. As @randall77 mentioned above, this is hard.

cherrymui · 2021-05-18T14:53:47Z

Thanks all for the investigation. I think we can close this.

Rajalakshmi-Girish changed the title ~~"TestKVWithEmptyValue" of etcd-io/etcd fails with Master golang~~ "TestKVWithEmptyValue" of etcd-io/etcd fails with master go Apr 22, 2021

cherrymui added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Apr 26, 2021

Rajalakshmi-Girish mentioned this issue May 18, 2021

Failing test: TestKVWithEmptyValue with master go on ppc64le etcd-io/etcd#12993

Closed

pacoxu mentioned this issue May 18, 2021

Kubernetes scheduler unit test registry_test Failures with master go kubernetes/kubernetes#101657

Closed

cherrymui closed this as completed May 18, 2021

golang locked and limited conversation to collaborators May 18, 2022

gopherbot added the FrozenDueToAge label May 18, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

"TestKVWithEmptyValue" of etcd-io/etcd fails with master go #45685

"TestKVWithEmptyValue" of etcd-io/etcd fails with master go #45685

Rajalakshmi-Girish commented Apr 22, 2021

Rajalakshmi-Girish commented Apr 22, 2021

laboger commented Apr 23, 2021

pmur commented Apr 23, 2021

pmur commented Apr 23, 2021

pmur commented Apr 23, 2021

cherrymui commented Apr 26, 2021

Rajalakshmi-Girish commented Apr 27, 2021

Rajalakshmi-Girish commented Apr 27, 2021

cherrymui commented Apr 27, 2021

laboger commented May 7, 2021

cherrymui commented May 7, 2021

laboger commented May 14, 2021

randall77 commented May 14, 2021

cherrymui commented May 14, 2021

Rajalakshmi-Girish commented May 18, 2021

cherrymui commented May 18, 2021

cherrymui commented May 18, 2021

"TestKVWithEmptyValue" of etcd-io/etcd fails with master go #45685

"TestKVWithEmptyValue" of etcd-io/etcd fails with master go #45685

Comments

Rajalakshmi-Girish commented Apr 22, 2021

What version of Go are you using (go version)?

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

What did you do?

What did you expect to see?

What did you see instead?

Rajalakshmi-Girish commented Apr 22, 2021

laboger commented Apr 23, 2021

pmur commented Apr 23, 2021

pmur commented Apr 23, 2021

pmur commented Apr 23, 2021

cherrymui commented Apr 26, 2021

Rajalakshmi-Girish commented Apr 27, 2021

Rajalakshmi-Girish commented Apr 27, 2021

cherrymui commented Apr 27, 2021

laboger commented May 7, 2021

cherrymui commented May 7, 2021

laboger commented May 14, 2021

randall77 commented May 14, 2021

cherrymui commented May 14, 2021

Rajalakshmi-Girish commented May 18, 2021

cherrymui commented May 18, 2021

cherrymui commented May 18, 2021

What version of Go are you using (`go version`)?

What operating system and processor architecture are you using (`go env`)?