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.

Sign up for GitHub

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

Jump to bottom

"connection reset by peer, received prior goaway: code: NO_ERROR" sometimes occur in agents #3177

Closed
hiyosi opened this issue Jun 21, 2022 · 16 comments
Closed

"connection reset by peer, received prior goaway: code: NO_ERROR" sometimes occur in agents #3177

hiyosi opened this issue Jun 21, 2022 · 16 comments
Labels
triage/in-progress Issue triage is in progress

Comments

@hiyosi
Copy link
Contributor

hiyosi commented Jun 21, 2022

  • Version: 1.3.0
  • Platform: Linux x86_64
  • Subsystem: agent

https://spiffe.slack.com/archives/C7XDP01HB/p1655716118861989

SPIRE Agents sometimes log received prior goaway: code: NO_ERROR
I can only see this error log when fetching bundles in my environment.

time="2022-06-10T22:42:15+09:00" level=error msg="Failed to fetch bundle" error="rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: read tcpxxx.xxx.xxx.xxx:33448->yyy.yyy.yyy.yyy:8081: read: connection reset by peer\", received prior goaway: code: NO_ERROR" subsystem_name=manager
time="2022-06-10T22:42:15+09:00" level=error msg="Synchronize failed" error="failed to fetch bundle: rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: read tcpxxx.xxx.xxx.xxx:33448->yyy.yyy.yyy.yyy:8081: read: connection reset by peer\", received prior goaway: code: NO_ERROR" subsystem_name=manager
time="2022-06-12T15:33:00+09:00" level=error msg="Failed to fetch bundle" error="rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: read tcpxxx.xxx.xxx.xxx:38594->yyy.yyy.yyy.yyy:8081: read: connection reset by peer\", received prior goaway: code: NO_ERROR" subsystem_name=manager
time="2022-06-12T15:33:00+09:00" level=error msg="Synchronize failed" error="failed to fetch bundle: rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: read tcpxxx.xxx.xxx.xxx:38594->yyy.yyy.yyy.yyy:8081: read: connection reset by peer\", received prior goaway: code: NO_ERROR" subsystem_name=manager
time="2022-06-16T17:45:14+09:00" level=error msg="Failed to fetch bundle" error="rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: read tcpxxx.xxx.xxx.xxx:51172->yyy.yyy.yyy.yyy:8081: read: connection reset by peer\", received prior goaway: code: NO_ERROR" subsystem_name=manager
time="2022-06-16T17:45:14+09:00" level=error msg="Synchronize failed" error="failed to fetch bundle: rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: read tcpxxx.xxx.xxx.xxx:51172->yyy.yyy.yyy.yyy:8081: read: connection reset by peer\", received prior goaway: code: NO_ERROR" subsystem_name=manager
time="2022-06-18T20:24:09+09:00" level=error msg="Failed to fetch bundle" error="rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: read tcpxxx.xxx.xxx.xxx:57638->yyy.yyy.yyy.yyy:8081: read: connection reset by peer\", received prior goaway: code: NO_ERROR" subsystem_name=manager
time="2022-06-18T20:24:09+09:00" level=error msg="Synchronize failed" error="failed to fetch bundle: rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: read tcpxxx.xxx.xxx.xxx:57638->yyy.yyy.yyy.yyy:8081: read: connection reset by peer\", received prior goaway: code: NO_ERROR" subsystem_name=manager

In my envionment, there is no L7 Proxy, only L4 LoadBalancer.

Agent  -- L4 LB --> Server
@amartinezfayo amartinezfayo added the triage/in-progress Issue triage is in progress label Jun 21, 2022
@azdagron
Copy link
Member

This is strange. Did you see this in versions prior to 1.3.0?

The "received prior goaway: code: NO_ERROR" suggests that the server terminated the http/2 connection, which is a little strange. The interval is also interesting, seems this is happening sporadically since it only seemed to happen every few days. Was the agent running the entire time?

The server is configured with a maximum connection age of 3 minutes. This means that it will intentionally reply to the client with a GOAWAY (NO_ERROR), which causes the client to reconnect. This is a mechanism we employ to help distribute load when new servers come up.

I wonder if the L4 load balancer is reusing the TCP connection that the server hasn't terminated yet (because it is waiting some time between sending the GOAWAY)....

Here are related issues:
grpc/grpc-go#5449
grpc/grpc-go#460

@hiyosi
Copy link
Contributor Author

hiyosi commented Jun 24, 2022

I can see the error with agent version 1.2.3 .

@azdagron
Copy link
Member

The interval is also interesting, seems this is happening sporadically since it only seemed to happen every few days. Was the agent running the entire time?

Do you know if the agent was running the entire time? That would help isolate the frequency of this event occurring.

@hiyosi
Copy link
Contributor Author

hiyosi commented Jun 28, 2022 •
edited
Loading

Yes, the agent was running the entire time.

@azdagron
Copy link
Member

azdagron commented Jun 30, 2022 •
edited
Loading

I'm not quite sure what is happening but it sounds like an issue in grpc-go working with the L4 load balancer. It might be difficult considering how sporadic it happens, but maybe we can collect detailed grpc logs?

https://github.com/grpc/grpc/blob/master/TROUBLESHOOTING.md

@hiyosi
Copy link
Contributor Author

hiyosi commented Jul 1, 2022

Thank you.
I'll collect additional logs.

@hiyosi
Copy link
Contributor Author

hiyosi commented Jul 8, 2022

So far, I founded the error on v1.2.0, v1.2.1, v1.3.0 environments.

I wonder the error always occur between fetchEntries() and fetchBundles() in agent.
And I have not been able to isolate whether it is a network problem or an application problem.

Following logs are captured on v1.2.0.

  • 13:22:36: received GOAWAY, connection reset by peer, received prior goaway: code: NO_ERROR was occurred.
  • 13:25:43: received GOAWAY, no error
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote HEADERS flags=END_HEADERS stream=141 len=16
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote DATA flags=END_STREAM stream=141 len=5 data="\x00\x00\x00\x00\x00"
2022/07/06 13:22:32 http2: Framer 0xc000651260: read WINDOW_UPDATE len=4 (conn) incr=5
2022/07/06 13:22:32 http2: Framer 0xc000651260: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:32 http2: Framer 0xc000651260: read HEADERS flags=END_HEADERS stream=141 len=2
2022/07/06 13:22:32 http2: decoded hpack field header field ":status" = "200"
2022/07/06 13:22:32 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:22:32 http2: Framer 0xc000651260: read DATA stream=141 len=373 data="[...MASK AUTHORIZED ENTRIES...]" (117 bytes omitted)
2022/07/06 13:22:32 http2: Framer 0xc000651260: read HEADERS flags=END_STREAM|END_HEADERS stream=141 len=2
2022/07/06 13:22:32 http2: decoded hpack field header field "grpc-status" = "0"
2022/07/06 13:22:32 http2: decoded hpack field header field "grpc-message" = ""
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote WINDOW_UPDATE len=4 (conn) incr=4123
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote HEADERS flags=END_HEADERS stream=143 len=16
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote DATA flags=END_STREAM stream=143 len=5 data="\x00\x00\x00\x00\x00"
2022/07/06 13:22:32 http2: Framer 0xc000651260: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:32 http2: Framer 0xc000651260: read WINDOW_UPDATE len=4 (conn) incr=5
2022/07/06 13:22:32 http2: Framer 0xc000651260: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:32 http2: Framer 0xc000651260: read HEADERS flags=END_HEADERS stream=143 len=2
2022/07/06 13:22:32 http2: decoded hpack field header field ":status" = "200"
2022/07/06 13:22:32 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:22:32 http2: Framer 0xc000651260: read DATA stream=143 len=16384 data="[...MASK BUNDLE DATA...]" (16128 bytes omitted)
2022/07/06 13:22:32 http2: Framer 0xc000651260: read DATA stream=143 len=16384 data="[...MASK BUNDLE DATA...]" (16128 bytes omitted)
2022/07/06 13:22:32 http2: Framer 0xc000651260: read DATA stream=143 len=3750 data="[...MASK BUNDLE DATA...]" (3494 bytes omitted)
2022/07/06 13:22:32 http2: Framer 0xc000651260: read HEADERS flags=END_STREAM|END_HEADERS stream=143 len=2
2022/07/06 13:22:32 http2: decoded hpack field header field "grpc-status" = "0"
2022/07/06 13:22:32 http2: decoded hpack field header field "grpc-message" = ""
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote WINDOW_UPDATE len=4 (conn) incr=16384
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote WINDOW_UPDATE len=4 (conn) incr=16384
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote WINDOW_UPDATE stream=143 len=4 incr=16384
2022/07/06 13:22:32 http2: Framer 0xc000651260: wrote WINDOW_UPDATE stream=143 len=4 incr=16384
2022/07/06 13:22:32 http2: Framer 0xc000651260: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:36 http2: Framer 0xc000651260: wrote HEADERS flags=END_HEADERS stream=145 len=8
2022/07/06 13:22:36 http2: Framer 0xc000651260: wrote DATA flags=END_STREAM stream=145 len=5 data="\x00\x00\x00\x00\x00"
2022/07/06 13:22:36 http2: Framer 0xc000651260: read WINDOW_UPDATE len=4 (conn) incr=5
2022/07/06 13:22:36 http2: Framer 0xc000651260: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:36 http2: Framer 0xc000651260: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:36 http2: Framer 0xc000651260: read HEADERS flags=END_HEADERS stream=145 len=2
2022/07/06 13:22:36 http2: decoded hpack field header field ":status" = "200"
2022/07/06 13:22:36 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:22:36 http2: Framer 0xc000651260: read DATA stream=145 len=373 data="[...MASK AUTHORIZED ENTRIES...]" (117 bytes omitted)
2022/07/06 13:22:36 http2: Framer 0xc000651260: read HEADERS flags=END_STREAM|END_HEADERS stream=145 len=2
2022/07/06 13:22:36 http2: decoded hpack field header field "grpc-status" = "0"
2022/07/06 13:22:36 http2: decoded hpack field header field "grpc-message" = ""
2022/07/06 13:22:36 http2: Framer 0xc000651260: wrote WINDOW_UPDATE len=4 (conn) incr=4123
2022/07/06 13:22:36 http2: Framer 0xc000651260: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:36 http2: Framer 0xc000651260: wrote HEADERS flags=END_HEADERS stream=147 len=16
2022/07/06 13:22:36 http2: Framer 0xc000651260: wrote DATA flags=END_STREAM stream=147 len=5 data="\x00\x00\x00\x00\x00"
2022/07/06 13:22:36 http2: Framer 0xc000651260: read GOAWAY len=8 LastStreamID=2147483647 ErrCode=NO_ERROR Debug=""
INFO: 2022/07/06 13:22:36 [core] Subchannel Connectivity change to CONNECTING
2022/07/06 13:22:36 http2: Framer 0xc000651260: read PING len=8 ping="\x01\x06\x01\b\x00\x03\x03\t"
INFO: 2022/07/06 13:22:36 [core] Subchannel picks a new address "[MASK SERVER IP]:443" to connect
2022/07/06 13:22:36 http2: Framer 0xc000651260: wrote PING flags=ACK len=8 ping="\x01\x06\x01\b\x00\x03\x03\t"
INFO: 2022/07/06 13:22:36 [balancer] base.baseBalancer: handle SubConn state change: 0xc0004d9210, CONNECTING
INFO: 2022/07/06 13:22:36 [roundrobin] roundrobinPicker: newPicker called with info: {map[]}
INFO: 2022/07/06 13:22:36 [core] Channel Connectivity change to CONNECTING
2022/07/06 13:22:36 http2: Framer 0xc000651260: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:36 http2: Framer 0xc000651260: read WINDOW_UPDATE len=4 (conn) incr=5
2022/07/06 13:22:36 http2: Framer 0xc000651260: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:36 http2: Framer 0xc000651260: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
INFO: 2022/07/06 13:22:36 [transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"
time="2022-07-06T13:22:36+09:00" level=error msg="Failed to fetch bundle" error="rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: read tcp [MASK CLIENT IP]:60402->[MASK SERVER IP]:443: read: connection reset by peer\", received prior goaway: code: NO_ERROR" subsystem_name=manager
INFO: 2022/07/06 13:22:36 [core] Channel Connectivity change to SHUTDOWN
INFO: 2022/07/06 13:22:36 [core] Subchannel Connectivity change to SHUTDOWN
time="2022-07-06T13:22:36+09:00" level=error msg="Synchronize failed" error="failed to fetch bundle: rpc error: code = Unavailable desc = closing transport due to: connection error: desc = \"error reading from server: read tcp [MASK CLIENT IP]:60402->[MASK SERVER IP]:443: read: connection reset by peer\", received prior goaway: code: NO_ERROR" subsystem_name=manager
WARNING: 2022/07/06 13:22:36 [core] grpc: addrConn.createTransport failed to connect to {[MASK SERVER IP]:443 [MASK SERVER IP]:443 <nil> 0 <nil>}. Err: connection error: desc = "transport: authentication handshake failed: context canceled". Reconnecting...
INFO: 2022/07/06 13:22:44 [core] parsed scheme: "dns"
INFO: 2022/07/06 13:22:44 [core] ccResolverWrapper: sending update to cc: {[{[MASK SERVER IP]:443  <nil> 0 <nil>}] <nil> <nil>}
INFO: 2022/07/06 13:22:44 [balancer] base.baseBalancer: got new ClientConn state:  {{[{[MASK SERVER IP]:443  <nil> 0 <nil>}] <nil> <nil>} <nil>}
INFO: 2022/07/06 13:22:44 [core] Subchannel Connectivity change to CONNECTING
INFO: 2022/07/06 13:22:44 [core] Subchannel picks a new address "[MASK SERVER IP]:443" to connect
INFO: 2022/07/06 13:22:44 [balancer] base.baseBalancer: handle SubConn state change: 0xc00207ae60, CONNECTING
INFO: 2022/07/06 13:22:44 [core] Channel Connectivity change to CONNECTING
2022/07/06 13:22:44 http2: Framer 0xc000650380: wrote HEADERS flags=END_HEADERS stream=1177 len=8
2022/07/06 13:22:44 http2: Framer 0xc000650380: wrote DATA flags=END_STREAM stream=1177 len=55 data="[... MASK DATA ...]"
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: read HEADERS flags=END_HEADERS stream=1177 len=8
2022/07/06 13:22:44 http2: decoded hpack field header field ":method" = "POST"
2022/07/06 13:22:44 http2: decoded hpack field header field ":scheme" = "http"
2022/07/06 13:22:44 http2: decoded hpack field header field ":path" = "/spire.plugin.agent.keymanager.v1.KeyManager/SignData"
2022/07/06 13:22:44 http2: decoded hpack field header field ":authority" = "IGNORED"
2022/07/06 13:22:44 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:22:44 http2: decoded hpack field header field "user-agent" = "grpc-go/1.40.0"
2022/07/06 13:22:44 http2: decoded hpack field header field "te" = "trailers"
2022/07/06 13:22:44 http2: decoded hpack field header field "grpc-timeout" = "29999965u"
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: read DATA flags=END_STREAM stream=1177 len=55 data="[... MASK DATA ...]"
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: wrote WINDOW_UPDATE len=4 (conn) incr=55
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000650380: read WINDOW_UPDATE len=4 (conn) incr=55
2022/07/06 13:22:44 http2: Framer 0xc000650380: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000650380: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: wrote HEADERS flags=END_HEADERS stream=1177 len=2
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: wrote DATA stream=1177 len=143 data="[... MASK DATA ...]"
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1177 len=2
2022/07/06 13:22:44 http2: Framer 0xc000650380: read HEADERS flags=END_HEADERS stream=1177 len=2
2022/07/06 13:22:44 http2: decoded hpack field header field ":status" = "200"
2022/07/06 13:22:44 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:22:44 http2: Framer 0xc000650380: read DATA stream=1177 len=143 data="[... MASK DATA ...]"
2022/07/06 13:22:44 http2: Framer 0xc000650380: read HEADERS flags=END_STREAM|END_HEADERS stream=1177 len=2
2022/07/06 13:22:44 http2: decoded hpack field header field "grpc-status" = "0"
2022/07/06 13:22:44 http2: decoded hpack field header field "grpc-message" = ""
2022/07/06 13:22:44 http2: Framer 0xc000650380: wrote WINDOW_UPDATE len=4 (conn) incr=143
2022/07/06 13:22:44 http2: Framer 0xc000650380: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: read WINDOW_UPDATE len=4 (conn) incr=143
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc0006501c0: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000650380: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote SETTINGS len=0
2022/07/06 13:22:44 http2: Framer 0xc000651420: read SETTINGS len=6, settings: MAX_FRAME_SIZE=16384
2022/07/06 13:22:44 http2: Framer 0xc000651420: read SETTINGS flags=ACK len=0
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote SETTINGS flags=ACK len=0
INFO: 2022/07/06 13:22:44 [core] Subchannel Connectivity change to READY
INFO: 2022/07/06 13:22:44 [balancer] base.baseBalancer: handle SubConn state change: 0xc00207ae60, READY
INFO: 2022/07/06 13:22:44 [roundrobin] roundrobinPicker: newPicker called with info: {map[0xc00207ae60:{{[MASK SERVER IP]:443  <nil> 0<nil>}}]}
INFO: 2022/07/06 13:22:44 [core] Channel Connectivity change to READY
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote HEADERS flags=END_HEADERS stream=1 len=110
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote DATA flags=END_STREAM stream=1 len=5 data="\x00\x00\x00\x00\x00"
2022/07/06 13:22:44 http2: Framer 0xc000651420: read WINDOW_UPDATE len=4 (conn) incr=5
2022/07/06 13:22:44 http2: Framer 0xc000651420: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000651420: read HEADERS flags=END_HEADERS stream=1 len=14
2022/07/06 13:22:44 http2: decoded hpack field header field ":status" = "200"
2022/07/06 13:22:44 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:22:44 http2: Framer 0xc000651420: read DATA stream=1 len=373 data="[...MASK AUTHORIZED ENTRIES...]" (117 bytes omitted)
2022/07/06 13:22:44 http2: Framer 0xc000651420: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=24
2022/07/06 13:22:44 http2: decoded hpack field header field "grpc-status" = "0"
2022/07/06 13:22:44 http2: decoded hpack field header field "grpc-message" = ""
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote WINDOW_UPDATE len=4 (conn) incr=373
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote HEADERS flags=END_HEADERS stream=3 len=50
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote DATA flags=END_STREAM stream=3 len=5 data="\x00\x00\x00\x00\x00"
2022/07/06 13:22:44 http2: Framer 0xc000651420: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000651420: read WINDOW_UPDATE len=4 (conn) incr=5
2022/07/06 13:22:44 http2: Framer 0xc000651420: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000651420: read HEADERS flags=END_HEADERS stream=3 len=2
2022/07/06 13:22:44 http2: decoded hpack field header field ":status" = "200"
2022/07/06 13:22:44 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:22:44 http2: Framer 0xc000651420: read DATA stream=3 len=16384 data="[...MASK BUNDLE DATA...]" (16128 bytes omitted)
2022/07/06 13:22:44 http2: Framer 0xc000651420: read DATA stream=3 len=16384 data="[...MASK BUNDLE DATA ...]" (16128 bytes omitted)
2022/07/06 13:22:44 http2: Framer 0xc000651420: read DATA stream=3 len=3750 data="[...MASK BUNDLE DATA ...]" (3494 bytes omitted)
2022/07/06 13:22:44 http2: Framer 0xc000651420: read HEADERS flags=END_STREAM|END_HEADERS stream=3 len=2
2022/07/06 13:22:44 http2: decoded hpack field header field "grpc-status" = "0"
2022/07/06 13:22:44 http2: decoded hpack field header field "grpc-message" = ""
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote WINDOW_UPDATE len=4 (conn) incr=16384
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote WINDOW_UPDATE stream=3 len=4 incr=16384
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote WINDOW_UPDATE len=4 (conn) incr=16384
2022/07/06 13:22:44 http2: Framer 0xc000651420: wrote WINDOW_UPDATE stream=3 len=4 incr=16384
2022/07/06 13:22:44 http2: Framer 0xc000651420: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote HEADERS flags=END_HEADERS stream=141 len=16
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote DATA flags=END_STREAM stream=141 len=5 data="\x00\x00\x00\x00\x00"
2022/07/06 13:25:42 http2: Framer 0xc000651420: read WINDOW_UPDATE len=4 (conn) incr=5
2022/07/06 13:25:42 http2: Framer 0xc000651420: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:42 http2: Framer 0xc000651420: read HEADERS flags=END_HEADERS stream=141 len=2
2022/07/06 13:25:42 http2: decoded hpack field header field ":status" = "200"
2022/07/06 13:25:42 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:25:42 http2: Framer 0xc000651420: read DATA stream=141 len=373 data="[...MASK AUTHORIZED ENTRIES...]" (117 bytes omitted)
2022/07/06 13:25:42 http2: Framer 0xc000651420: read HEADERS flags=END_STREAM|END_HEADERS stream=141 len=2
2022/07/06 13:25:42 http2: decoded hpack field header field "grpc-status" = "0"
2022/07/06 13:25:42 http2: decoded hpack field header field "grpc-message" = ""
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote WINDOW_UPDATE len=4 (conn) incr=4123
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote HEADERS flags=END_HEADERS stream=143 len=16
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote DATA flags=END_STREAM stream=143 len=5 data="\x00\x00\x00\x00\x00"
2022/07/06 13:25:42 http2: Framer 0xc000651420: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:42 http2: Framer 0xc000651420: read WINDOW_UPDATE len=4 (conn) incr=5
2022/07/06 13:25:42 http2: Framer 0xc000651420: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:42 http2: Framer 0xc000651420: read HEADERS flags=END_HEADERS stream=143 len=2
2022/07/06 13:25:42 http2: decoded hpack field header field ":status" = "200"
2022/07/06 13:25:42 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:25:42 http2: Framer 0xc000651420: read DATA stream=143 len=16384 data="[...MASK BUNDLE DATA...]" (16128 bytes omitted)
2022/07/06 13:25:42 http2: Framer 0xc000651420: read DATA stream=143 len=16384 data="[...MASK BUNDLE DATA...]" (16128 bytes omitted)
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote WINDOW_UPDATE len=4 (conn) incr=16384
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote WINDOW_UPDATE len=4 (conn) incr=16384
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote WINDOW_UPDATE stream=143 len=4 incr=16384
2022/07/06 13:25:42 http2: Framer 0xc000651420: wrote WINDOW_UPDATE stream=143 len=4 incr=16384
2022/07/06 13:25:42 http2: Framer 0xc000651420: read DATA stream=143 len=3750 data="[...MASK BUNDLE DATA...]" (3494 bytes omitted)
2022/07/06 13:25:42 http2: Framer 0xc000651420: read HEADERS flags=END_STREAM|END_HEADERS stream=143 len=2
2022/07/06 13:25:42 http2: decoded hpack field header field "grpc-status" = "0"
2022/07/06 13:25:42 http2: decoded hpack field header field "grpc-message" = ""
2022/07/06 13:25:42 http2: Framer 0xc000651420: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:43 http2: Framer 0xc000651420: read GOAWAY len=8 LastStreamID=2147483647 ErrCode=NO_ERROR Debug=""
INFO: 2022/07/06 13:25:43 [core] Subchannel Connectivity change to CONNECTING
INFO: 2022/07/06 13:25:43 [balancer] base.baseBalancer: handle SubConn state change: 0xc00207ae60, CONNECTING
2022/07/06 13:25:43 http2: Framer 0xc000651420: read PING len=8 ping="\x01\x06\x01\b\x00\x03\x03\t"
INFO: 2022/07/06 13:25:43 [roundrobin] roundrobinPicker: newPicker called with info: {map[]}
INFO: 2022/07/06 13:25:43 [core] Subchannel picks a new address "[MASK SERVER IP]:443" to connect
INFO: 2022/07/06 13:25:43 [transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"
INFO: 2022/07/06 13:25:43 [core] Channel Connectivity change to CONNECTING
2022/07/06 13:25:43 http2: Framer 0xc000650380: wrote HEADERS flags=END_HEADERS stream=1179 len=8
2022/07/06 13:25:43 http2: Framer 0xc000650380: wrote DATA flags=END_STREAM stream=1179 len=55 data="[...MASK DATA...]"
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: read HEADERS flags=END_HEADERS stream=1179 len=8
2022/07/06 13:25:43 http2: decoded hpack field header field ":method" = "POST"
2022/07/06 13:25:43 http2: decoded hpack field header field ":scheme" = "http"
2022/07/06 13:25:43 http2: decoded hpack field header field ":path" = "/spire.plugin.agent.keymanager.v1.KeyManager/SignData"
2022/07/06 13:25:43 http2: decoded hpack field header field ":authority" = "IGNORED"
2022/07/06 13:25:43 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:25:43 http2: decoded hpack field header field "user-agent" = "grpc-go/1.40.0"
2022/07/06 13:25:43 http2: decoded hpack field header field "te" = "trailers"
2022/07/06 13:25:43 http2: decoded hpack field header field "grpc-timeout" = "29999972u"
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: read DATA flags=END_STREAM stream=1179 len=55 data="[...MASK DATA...]"
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: wrote WINDOW_UPDATE len=4 (conn) incr=55
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:43 http2: Framer 0xc000650380: read WINDOW_UPDATE len=4 (conn) incr=55
2022/07/06 13:25:43 http2: Framer 0xc000650380: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:43 http2: Framer 0xc000650380: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: wrote HEADERS flags=END_HEADERS stream=1179 len=2
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: wrote DATA stream=1179 len=145 data="[...MASK DATA...]"
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1179 len=2
2022/07/06 13:25:43 http2: Framer 0xc000650380: read HEADERS flags=END_HEADERS stream=1179 len=2
2022/07/06 13:25:43 http2: decoded hpack field header field ":status" = "200"
2022/07/06 13:25:43 http2: decoded hpack field header field "content-type" = "application/grpc"
2022/07/06 13:25:43 http2: Framer 0xc000650380: read DATA stream=1179 len=145 data="[...MASK DATA...]"
2022/07/06 13:25:43 http2: Framer 0xc000650380: read HEADERS flags=END_STREAM|END_HEADERS stream=1179 len=2
2022/07/06 13:25:43 http2: decoded hpack field header field "grpc-status" = "0"
2022/07/06 13:25:43 http2: decoded hpack field header field "grpc-message" = ""
2022/07/06 13:25:43 http2: Framer 0xc000650380: wrote WINDOW_UPDATE len=4 (conn) incr=145
2022/07/06 13:25:43 http2: Framer 0xc000650380: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: read WINDOW_UPDATE len=4 (conn) incr=145
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:43 http2: Framer 0xc0006501c0: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:43 http2: Framer 0xc000650380: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2022/07/06 13:25:43 http2: Framer 0xc000a2fdc0: wrote SETTINGS len=0
2022/07/06 13:25:43 http2: Framer 0xc000a2fdc0: read SETTINGS len=6, settings: MAX_FRAME_SIZE=16384
2022/07/06 13:25:43 http2: Framer 0xc000a2fdc0: read SETTINGS flags=ACK len=0
INFO: 2022/07/06 13:25:43 [core] Subchannel Connectivity change to READY
INFO: 2022/07/06 13:25:43 [balancer] base.baseBalancer: handle SubConn state change: 0xc00207ae60, READY
2022/07/06 13:25:43 http2: Framer 0xc000a2fdc0: wrote SETTINGS flags=ACK len=0
INFO: 2022/07/06 13:25:43 [roundrobin] roundrobinPicker: newPicker called with info: {map[0xc00207ae60:{{[MASK SERVER IP]:443  <nil> 0<nil>}}]}
INFO: 2022/07/06 13:25:43 [core] Channel Connectivity change to READY

@hiyosi hiyosi changed the title "received prior goaway: code: NO_ERROR" sometimes occur in agents "connection reset by peer, received prior goaway: code: NO_ERROR" sometimes occur in agents Jul 8, 2022
@azdagron
Copy link
Member

azdagron commented Jul 8, 2022

Is there a way to test this without the L4 load balancer in the middle?

@hiyosi
Copy link
Contributor Author

hiyosi commented Jul 18, 2022

Is there a way to test this without the L4 load balancer in the middle?

I need some time to prepare this environment. I will report the results shortly.

Additional info.
I changed the sync_interval of the agent, but the error occurs at the same point.

@azdagron
Copy link
Member

azdagron commented Aug 2, 2022

Any updates here, @hiyosi ?

@hiyosi
Copy link
Contributor Author

hiyosi commented Aug 4, 2022

sorry, It's still going to take some time.

@azdagron
Copy link
Member

azdagron commented Aug 4, 2022

No worries!

@evan2645
Copy link
Member

evan2645 commented Sep 6, 2022

Thank you very much for reporting this issue @hiyosi . We discussed it again today on our contributor call ... the gRPC library has been recently updated in SPIRE - is there any way you can check with the latest code to see if the problem is still there? I thought maybe this would be easier than testing without the load balancer.

I wonder if the L4 load balancer is reusing the TCP connection that the server hasn't terminated yet (because it is waiting some time between sending the GOAWAY)....

This sounds super likely when considering that SPIRE Server does not log anything (which I think it would if it received unexpected RST from a client). TCP connection pooling is also a known feature/optimization frequently used in L4 load balancing.

If it is ok with you, we will go ahead and close this issue in two weeks if you're not able to do any additional testing by then. We're happy to re-open it whenever you are ready!

@hiyosi
Copy link
Contributor Author

hiyosi commented Sep 7, 2022

I will do my best to report back to here within the next two weeks.

@evan2645
Copy link
Member

Hey @hiyosi - thank you again for reporting this! We understand you are busy and it takes time to test, we don't want you to feel any pressure here. If you're able to find some time to test, please do post back here and let us know what you find. In the meantime, I'm going to close this issue out

@hiyosi
Copy link
Contributor Author

hiyosi commented May 8, 2023

This may be related htps://github.com/grpc/grpc-go/issues/6019.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
triage/in-progress Issue triage is in progress
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@hiyosi @evan2645 @azdagron @amartinezfayo