Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
Rajalakshmi-Girish opened this issue Apr 22, 2021 · 17 comments
Closed

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

Rajalakshmi-Girish opened this issue Apr 22, 2021 · 17 comments

Comments

@Rajalakshmi-Girish
Copy link

@Rajalakshmi-Girish Rajalakshmi-Girish commented Apr 22, 2021

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

@Rajalakshmi-Girish
Copy link
Author

@Rajalakshmi-Girish Rajalakshmi-Girish commented Apr 22, 2021

@laboger Can you please give some pointers?

@Rajalakshmi-Girish 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
@laboger
Copy link
Contributor

@laboger laboger commented Apr 23, 2021

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

@pmur

@pmur
Copy link
Contributor

@pmur pmur commented Apr 23, 2021

Bisecting this failure, it started with 9a555fc

@pmur
Copy link
Contributor

@pmur pmur commented Apr 23, 2021

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

@pmur
Copy link
Contributor

@pmur pmur commented Apr 23, 2021

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
Copy link
Contributor

@cherrymui cherrymui commented Apr 26, 2021

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

@Rajalakshmi-Girish
Copy link
Author

@Rajalakshmi-Girish Rajalakshmi-Girish commented Apr 27, 2021

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
Copy link
Author

@Rajalakshmi-Girish Rajalakshmi-Girish commented Apr 27, 2021

@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
Copy link
Contributor

@cherrymui cherrymui commented Apr 27, 2021

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
Copy link
Contributor

@laboger laboger commented May 7, 2021

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
Copy link
Contributor

@cherrymui cherrymui commented May 7, 2021

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
Copy link
Contributor

@laboger laboger commented May 14, 2021

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
Copy link
Contributor

@randall77 randall77 commented May 14, 2021

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
Copy link
Contributor

@cherrymui cherrymui commented May 14, 2021

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
Copy link
Author

@Rajalakshmi-Girish Rajalakshmi-Girish commented May 18, 2021

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
Copy link
Contributor

@cherrymui cherrymui commented May 18, 2021

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
Copy link
Contributor

@cherrymui cherrymui commented May 18, 2021

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

@cherrymui cherrymui closed this May 18, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
5 participants