Gate doesn't get tree from other node (round robin)

anikeev-yadro commented

2023-05-17 10:24:42 +00:00

Expected Behavior

Gate should get tree info from some endpoins according config. And return the error after try to use all endpoints from config.

Current Behavior

Gate try to get tree info from one (not first in config list) endpoin and return the error.

Steps to Reproduce (for bugs)

1.Start s3 k6 load to nodes 1-3
2.Reboot node4
3.See errors in k6 log:

20:32:04] operation error S3: GetObject, https response error StatusCode: 500, RequestID: baa89317-3aff-4395-aedc-2431cc551bdf, HostID: 272a6148-200e-4d3e-93a7-77e7e0c641bd, api error InternalError: We encountered an internal error, please try again.  [31mbucket[0m=67f649d7-d7b1-4cd2-92d0-7f81a504b837 [31mendpoint[0m="10.78.70.148:8084" [31mkey[0m=2765f0e1-3c9b-4568-88d1-b66976ffd634

In node log same time error:

service@az:~$ journalctl --utc -S  "2023-05-16 20:30:00" --no-pager|grep baa89317-3aff-4395-aedc-2431cc551bdf
May 16 20:32:04 az frostfs-s3-gw[8417]: 2023-05-16T20:32:04.229Z        error        handler/util.go:29        call method        {"status": 500, "request_id": "baa89317-3aff-4395-aedc-2431cc551bdf", "method": "GetObject", "bucket": "67f649d7-d7b1-4cd2-92d0-7f81a504b837", "object": "2765f0e1-3c9b-4568-88d1-b66976ffd634", "description": "could not get bucket settings", "error": "couldn't get node: failed to get node by path: rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 192.168.201.151:8080: connect: connection refused\""}
May 16 20:32:04 az frostfs-s3-gw[8417]: 2023-05-16T20:32:04.232Z        info        layer/layer.go:703        resolve bucket        {"reqId": "baa89317-3aff-4395-aedc-2431cc551bdf", "bucket": "67f649d7-d7b1-4cd2-92d0-7f81a504b837", "cid": "F9NVyA3X5QUnHa6qm49U6SiACGzTtQHprAZhRaE3LBbs"}

s3 config for tree:

tree:
    service:
    - localhost:8080
    - 192.168.201.49:8080
    - 192.168.201.51:8080
    - 192.168.201.50:8080
    - 192.168.201.149:8080
    - 192.168.201.151:8080
    - 192.168.201.150:8080

Context

This affected faiover tests with reboot node.

Regression

Yes

Version

FrostFS S3 Gateway
Version: v0.27.0-rc.2
GoVersion: go1.18.4

Your Environment

HW
4 nodes

## Expected Behavior Gate should get tree info from some endpoins according config. And return the error after try to use all endpoints from config. ## Current Behavior Gate try to get tree info from one (not first in config list) endpoin and return the error. ## Steps to Reproduce (for bugs) 1.Start s3 k6 load to nodes 1-3 2.Reboot node4 3.See errors in k6 log: ``` 20:32:04] operation error S3: GetObject, https response error StatusCode: 500, RequestID: baa89317-3aff-4395-aedc-2431cc551bdf, HostID: 272a6148-200e-4d3e-93a7-77e7e0c641bd, api error InternalError: We encountered an internal error, please try again. [31mbucket[0m=67f649d7-d7b1-4cd2-92d0-7f81a504b837 [31mendpoint[0m="10.78.70.148:8084" [31mkey[0m=2765f0e1-3c9b-4568-88d1-b66976ffd634 ``` In node log same time error: ``` service@az:~$ journalctl --utc -S "2023-05-16 20:30:00" --no-pager|grep baa89317-3aff-4395-aedc-2431cc551bdf May 16 20:32:04 az frostfs-s3-gw[8417]: 2023-05-16T20:32:04.229Z error handler/util.go:29 call method {"status": 500, "request_id": "baa89317-3aff-4395-aedc-2431cc551bdf", "method": "GetObject", "bucket": "67f649d7-d7b1-4cd2-92d0-7f81a504b837", "object": "2765f0e1-3c9b-4568-88d1-b66976ffd634", "description": "could not get bucket settings", "error": "couldn't get node: failed to get node by path: rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 192.168.201.151:8080: connect: connection refused\""} May 16 20:32:04 az frostfs-s3-gw[8417]: 2023-05-16T20:32:04.232Z info layer/layer.go:703 resolve bucket {"reqId": "baa89317-3aff-4395-aedc-2431cc551bdf", "bucket": "67f649d7-d7b1-4cd2-92d0-7f81a504b837", "cid": "F9NVyA3X5QUnHa6qm49U6SiACGzTtQHprAZhRaE3LBbs"} ``` s3 config for tree: ``` tree: service: - localhost:8080 - 192.168.201.49:8080 - 192.168.201.51:8080 - 192.168.201.50:8080 - 192.168.201.149:8080 - 192.168.201.151:8080 - 192.168.201.150:8080 ``` ## Context This affected faiover tests with reboot node. ## Regression Yes ## Version ``` FrostFS S3 Gateway Version: v0.27.0-rc.2 GoVersion: go1.18.4 ``` ## Your Environment HW 4 nodes

anikeev-yadro added the

bug

label 2023-05-17 10:24:42 +00:00

alexvanin self-assigned this 2023-05-17 10:25:38 +00:00

alexvanin added this to the v0.27.0 milestone 2023-05-17 10:25:46 +00:00

dkirillov commented

2023-05-17 10:46:16 +00:00

Collaborator

@anikeev-yadro Could you enable debug log level? We should see switching info when request if failed

@anikeev-yadro Could you enable `debug` log level? We should see switching info when request if failed

alexvanin commented

2023-05-17 11:27:39 +00:00

Owner

I got some logs related to that. By the way it would be nice to pass request id deep down to any function that produce log records. So it would be easier to find.

This test may pass sometimes.
I see such records on a failed run:

tree request error        {"address": "192.168.201.150:8080", "error": "not found: rpc error: code = Unknown desc = tree not found"}
tree request error        {"address": "192.168.201.49:8080", "error": "not found: rpc error: code = Unknown desc = tree not found"}
tree request error        {"address": "192.168.201.51:8080", "error": "failed to get node by path: rpc error: code = Unavailable desc = error reading from server: read tcp 192.168.201.48:34160->192.168.201.51:8080: read: connection reset by peer"}
...
tree request error        {"addres": "192.168.201.51:8080", "error": "failed to get node by path: rpc error: code = Unavailable desc = error reading from server: read tcp 192.168.201.48:34160->192.168.201.51:8080: read: connection reset by peer"}
tree request error        {"address": "192.168.201.50:8080", "error": "not found: rpc error: code = Unknown desc = tree not found"}
...
tree request error        {"address": "192.168.201.149:8080", "error": "not found: rpc error: code = Unknown desc = tree not found"}
tree request error        {"address": "192.168.201.151:8080", "error": "failed to get node by path: rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 192.168.201.151:8080: connect: connection refused\""}
...

So it seems that GW does iterate over endpoints, but:

it misses localhost endpoint for some reason,
.51 and .151 return connection errors which is expected
remaining .49 and .50 return tree not found.

Imagine that container and the tree is stored in .48 (localhost) and .51 nodes. In this case, if storage node does not resend requests, we got this behaviour.

I got some logs related to that. By the way it would be nice to pass request id deep down to any function that produce log records. So it would be easier to find. 1. This test may pass sometimes. 2. I see such records on a failed run: ``` tree request error {"address": "192.168.201.150:8080", "error": "not found: rpc error: code = Unknown desc = tree not found"} tree request error {"address": "192.168.201.49:8080", "error": "not found: rpc error: code = Unknown desc = tree not found"} tree request error {"address": "192.168.201.51:8080", "error": "failed to get node by path: rpc error: code = Unavailable desc = error reading from server: read tcp 192.168.201.48:34160->192.168.201.51:8080: read: connection reset by peer"} ... tree request error {"addres": "192.168.201.51:8080", "error": "failed to get node by path: rpc error: code = Unavailable desc = error reading from server: read tcp 192.168.201.48:34160->192.168.201.51:8080: read: connection reset by peer"} tree request error {"address": "192.168.201.50:8080", "error": "not found: rpc error: code = Unknown desc = tree not found"} ... tree request error {"address": "192.168.201.149:8080", "error": "not found: rpc error: code = Unknown desc = tree not found"} tree request error {"address": "192.168.201.151:8080", "error": "failed to get node by path: rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 192.168.201.151:8080: connect: connection refused\""} ... ``` So it seems that GW does iterate over endpoints, but: - it misses localhost endpoint for some reason, - .51 and .151 return connection errors which is expected - remaining .49 and .50 return `tree not found`. Imagine that container and the tree is stored in .48 (localhost) and .51 nodes. In this case, if storage node does not resend requests, we got this behaviour.

alexvanin commented

2023-05-17 14:49:22 +00:00

Owner

We see two issues there:

In some cases S3 gateway expects tree not found errors and does not require to iterate over all available endpoints. In this issue, S3 gateway iterates over all nodes and gets connection refused error on last endpoint, which breaks request execution. We fix it there.
However in the logs we see that S3 gateway may start before storage node and it eliminates localhost endpoint from the pool of tree service addresses. For now we want to update unit file for strict startup order, but we should consider something similar to pool healthchecks for tree service endpoints.

We see two issues there: 1) In some cases S3 gateway expects `tree not found` errors and does not require to iterate over all available endpoints. In this issue, S3 gateway iterates over all nodes and gets `connection refused` error on last endpoint, which breaks request execution. We fix it there. 2) However in the logs we see that S3 gateway may start before storage node and it eliminates localhost endpoint from the pool of tree service addresses. For now we want to update unit file for strict startup order, but we should consider something similar to pool healthchecks for tree service endpoints.

alexvanin removed their assignment 2023-05-17 14:49:29 +00:00

dkirillov was assigned by alexvanin

2023-05-17 14:49:29 +00:00

anikeev-yadro commented

2023-05-18 10:20:22 +00:00

Poster

I think that update unit file for strict startup order won't help us. Because storage node return 'Active' state to systemd earlier than it open localhost socket.
@fyrchik please confirm.

I think that update unit file for strict startup order won't help us. Because storage node return 'Active' state to systemd earlier than it open localhost socket. @fyrchik please confirm.

dkirillov referenced a pull request that will close this issue

2023-05-19 14:12:11 +00:00

Improve tree node switching #115

alexvanin referenced this issue from a commit

2023-05-22 10:58:35 +00:00

[#110] tree: Update errors to switch endpoint

alexvanin referenced this issue from a commit

2023-05-22 10:58:35 +00:00

[#110] tree: Add more logs for switching tree endpoints

alexvanin closed this issue

2023-05-22 10:58:35 +00:00

alexvanin referenced this issue from a commit