Skip to content
This repository has been archived by the owner on Feb 9, 2024. It is now read-only.

[5.5.x] system debug endpoint in container #1579

Merged
merged 1 commit into from
May 20, 2020
Merged

[5.5.x] system debug endpoint in container #1579

merged 1 commit into from
May 20, 2020

Conversation

a-palchikov
Copy link
Contributor

Description

This PR adds support for debug endpoint inside the Planet container. The endpoint is only query-able from the node locally - using the dedicated planet debug-status command.

Type of change

  • New feature (non-breaking change which adds functionality)
  • Internal change (not necessarily a bug fix or a new feature)

Linked tickets and other PRs

TODOs

  • Self-review the change
  • Perform manual testing
  • Address review feedback

Implementation

Testing done

  • Install a single-node as well as 3-node clusters.
  • Ensure that gravity status works as expected
  • Ensure that the agent can be manually stopped/restarted
  • Ensure that the new command planet debug-status reports the goroutine profile as text.

@a-palchikov a-palchikov requested review from a team, r0mant and knisbet May 18, 2020 17:55
@a-palchikov a-palchikov force-pushed the dmitri/5.5.x/1091-agent branch 2 times, most recently from 324a2d8 to 0cac4cf Compare May 20, 2020 16:43
@r0mant
Copy link
Contributor

r0mant commented May 20, 2020

Seems like robotest passed but CI failed due to a racy test. Verified the test locally, going to merge.

➜  gravity git:(dmitri/5.5.x/1091-agent) p=lib/rpc/... make test-package
TEST_ETCD=false TEST_ETCD_CONFIG='{"nodes": ["https://localhost:4001"], "key":"/gravity/test", "tls_key_file": "/code/go/src/github.com/gravitational/gravity/assets/certs/proxy1-key.pem", "tls_cert_file": "/code/go/src/github.com/gravitational/gravity/assets/certs/proxy1.pem", "tls_ca_file": "/code/go/src/github.com/gravitational/gravity/assets/certs/ca.pem"}' TEST_K8S=false go test -v ./lib/rpc/...
?   	github.com/gravitational/gravity/lib/rpc	[no test files]
?   	github.com/gravitational/gravity/lib/rpc/client	[no test files]
=== RUN   TestConn
=== RUN   TestConn/BasicIO
=== RUN   TestConn/PingPong
=== RUN   TestConn/RacyRead
=== RUN   TestConn/RacyWrite
=== RUN   TestConn/ReadTimeout
=== RUN   TestConn/WriteTimeout
=== RUN   TestConn/PastTimeout
=== RUN   TestConn/PresentTimeout
=== RUN   TestConn/FutureTimeout
=== RUN   TestConn/CloseTimeout
=== RUN   TestConn/ConcurrentMethods
--- PASS: TestConn (0.33s)
    --- PASS: TestConn/BasicIO (0.01s)
    --- PASS: TestConn/PingPong (0.00s)
    --- PASS: TestConn/RacyRead (0.00s)
    --- PASS: TestConn/RacyWrite (0.00s)
    --- PASS: TestConn/ReadTimeout (0.00s)
    --- PASS: TestConn/WriteTimeout (0.00s)
    --- PASS: TestConn/PastTimeout (0.00s)
    --- PASS: TestConn/PresentTimeout (0.10s)
    --- PASS: TestConn/FutureTimeout (0.10s)
    --- PASS: TestConn/CloseTimeout (0.11s)
    --- PASS: TestConn/ConcurrentMethods (0.00s)
PASS
ok  	github.com/gravitational/gravity/lib/rpc/inprocess	(cached)
?   	github.com/gravitational/gravity/lib/rpc/proto	[no test files]
=== RUN   TestProxy
time="2020-05-20T14:38:07-07:00" level=info msg="Proxy started." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Accept connection from pipe." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Upstream connection to pipe." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=error msg="Failed to accept: closed." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Proxy stopped." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Proxy started." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Accept connection from pipe." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Upstream connection to pipe." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=error msg="Failed to accept: closed." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Proxy stopped." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Proxy stopped." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Proxy started." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Accept connection from pipe." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Upstream connection to pipe." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=error msg="Failed to accept: closed." proxy=localLink
time="2020-05-20T14:38:07-07:00" level=info msg="Proxy stopped." proxy=localLink
OK: 2 passed
--- PASS: TestProxy (0.00s)
PASS
ok  	github.com/gravitational/gravity/lib/rpc/proxy	(cached)
=== RUN   TestServer
time="2020-05-20T14:37:56-07:00" level=info msg=Monitoring. monitored="198.51.100.1:6767" trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Reconnecting reconnected="peer(addr=198.51.100.1:6767)" trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Retrying in 599.794713ms." error="context deadline exceeded"
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=198.51.100.1:6767)" trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring loop closing." monitored="198.51.100.1:6767" trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=198.51.100.1:6767)" trace.component=peers
time="2020-05-20T14:37:56-07:00" level=warning msg="All attempts failed." error="context deadline exceeded"
time="2020-05-20T14:37:56-07:00" level=info msg="Reconnect loop closing." reconnected="peer(addr=198.51.100.1:6767)" trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Listening. addr="127.0.0.1:40897" from="127.0.0.1:40897" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=info msg=Listening. addr="127.0.0.1:40365" peer="127.0.0.1:40365" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:40897)" peer="127.0.0.1:40365" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Monitoring. monitored="127.0.0.1:40897" peer="127.0.0.1:40365" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Listening. addr="127.0.0.1:36677" peer="127.0.0.1:36677" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=info msg=Reconnecting peer="127.0.0.1:36677" reconnected="peer(addr=127.0.0.1:36677->server=127.0.0.1:40897)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Monitoring. monitored="127.0.0.1:40897" peer="127.0.0.1:36677" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Reconnecting peer="127.0.0.1:40365" reconnected="peer(addr=127.0.0.1:40365->server=127.0.0.1:40897)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:40897)" peer="127.0.0.1:36677" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=debug msg=PeerJoin. from="127.0.0.1:40897" req="PeerJoinRequest(addr=127.0.0.1:36677, config=)" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=debug msg=PeerJoin. from="127.0.0.1:40897" req="PeerJoinRequest(addr=127.0.0.1:40365, config=)" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:36677),peer(addr=127.0.0.1:40365)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Monitoring. monitored="127.0.0.1:36677" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Monitoring. monitored="127.0.0.1:40365" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Reconnecting reconnected="peer(addr=127.0.0.1:40365)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Peer reconnected." peer="127.0.0.1:36677" reconnected="peer(addr=127.0.0.1:36677->server=127.0.0.1:40897)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Reconnecting reconnected="peer(addr=127.0.0.1:36677)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Peer reconnected." peer="127.0.0.1:40365" reconnected="peer(addr=127.0.0.1:40365->server=127.0.0.1:40897)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Dropped update notification for watchEvent(peer(addr=127.0.0.1:40365->server=127.0.0.1:40897), client=&{0xc0002924b8 0xc0002924c0 0xc000386300}, error=<nil>)." health.checker="peer(addr=127.0.0.1:40897)" peer="127.0.0.1:40365" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Peer reconnected." reconnected="peer(addr=127.0.0.1:40365)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Peer reconnected." reconnected="peer(addr=127.0.0.1:36677)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=debug msg="request received" args="[test]" peer="127.0.0.1:40365" request=Command test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=info msg="Dropped update notification for watchEvent(peer(addr=127.0.0.1:36677->server=127.0.0.1:40897), client=&{0xc00019c080 0xc00019c0d8 0xc000386000}, error=<nil>)." health.checker="peer(addr=127.0.0.1:40897)" peer="127.0.0.1:36677" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=debug msg="completed OK" args="[test]" peer="127.0.0.1:40365" request=Command test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=debug msg="Run [\"test\"]." seq=1 test=AgentGroupExecutesCommandsRemotety trace.component=rpc
time="2020-05-20T14:37:56-07:00" level=info msg="\"test output\"" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=debug msg=Completed. exit=0 seq=1 test=AgentGroupExecutesCommandsRemotety trace.component=rpc
time="2020-05-20T14:37:56-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:36677),peer(addr=127.0.0.1:40365)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:36677" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Reconnect loop closing." reconnected="peer(addr=127.0.0.1:36677)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:40365" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Reconnect loop closing." reconnected="peer(addr=127.0.0.1:40365)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=debug msg=PeerLeave. from="127.0.0.1:40897" req="PeerLeaveRequest(addr=127.0.0.1:40365, config=)" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:40897)" peer="127.0.0.1:40365" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:40897" peer="127.0.0.1:40365" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Reconnect loop closing." peer="127.0.0.1:40365" reconnected="peer(addr=127.0.0.1:40365->server=127.0.0.1:40897)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Server stopped." error="<nil>" peer="127.0.0.1:40365" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=debug msg=PeerLeave. from="127.0.0.1:40897" req="PeerLeaveRequest(addr=127.0.0.1:36677, config=)" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:40897" peer="127.0.0.1:36677" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Server stopped." error="<nil>" peer="127.0.0.1:36677" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:40897)" peer="127.0.0.1:36677" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Reconnect loop closing." peer="127.0.0.1:36677" reconnected="peer(addr=127.0.0.1:36677->server=127.0.0.1:40897)" test=AgentGroupExecutesCommandsRemotety trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Server stopped." error="<nil>" from="127.0.0.1:40897" test=AgentGroupExecutesCommandsRemotety
time="2020-05-20T14:37:56-07:00" level=info msg="Proxy started." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:56-07:00" level=info msg=Listening. addr="127.0.0.1:42571" peer="127.0.0.1:42571" test=AgentGroupReconnects
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:41119)" peer="127.0.0.1:42571" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Listening. addr="127.0.0.1:41119" server="127.0.0.1:41119" test=AgentGroupReconnects
time="2020-05-20T14:37:56-07:00" level=info msg=Listening. addr="127.0.0.1:42907" peer="127.0.0.1:42907" test=AgentGroupReconnects
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:41119)" peer="127.0.0.1:42907" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Monitoring. monitored="127.0.0.1:41119" peer="127.0.0.1:42571" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Reconnecting peer="127.0.0.1:42571" reconnected="peer(addr=127.0.0.1:40099->server=127.0.0.1:41119)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Monitoring. monitored="127.0.0.1:41119" peer="127.0.0.1:42907" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Reconnecting peer="127.0.0.1:42907" reconnected="peer(addr=127.0.0.1:42907->server=127.0.0.1:41119)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=debug msg=PeerJoin. req="PeerJoinRequest(addr=127.0.0.1:42907, config=)" server="127.0.0.1:41119" test=AgentGroupReconnects
time="2020-05-20T14:37:56-07:00" level=info msg="Peer reconnected." peer="127.0.0.1:42907" reconnected="peer(addr=127.0.0.1:42907->server=127.0.0.1:41119)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Dropped update notification for watchEvent(peer(addr=127.0.0.1:42907->server=127.0.0.1:41119), client=&{0xc000010150 0xc000010158 0xc0003b2600}, error=<nil>)." health.checker="peer(addr=127.0.0.1:41119)" peer="127.0.0.1:42907" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=debug msg=PeerJoin. req="PeerJoinRequest(addr=127.0.0.1:40099, config=)" server="127.0.0.1:41119" test=AgentGroupReconnects
time="2020-05-20T14:37:56-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:42907),peer(addr=127.0.0.1:40099)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Peer reconnected." peer="127.0.0.1:42571" reconnected="peer(addr=127.0.0.1:40099->server=127.0.0.1:41119)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Dropped update notification for watchEvent(peer(addr=127.0.0.1:40099->server=127.0.0.1:41119), client=&{0xc0000fa1a8 0xc0000fa1b8 0xc00063bb00}, error=<nil>)." health.checker="peer(addr=127.0.0.1:41119)" peer="127.0.0.1:42571" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Monitoring. monitored="127.0.0.1:42907" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Reconnecting reconnected="peer(addr=127.0.0.1:42907)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Monitoring. monitored="127.0.0.1:40099" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg=Reconnecting reconnected="peer(addr=127.0.0.1:40099)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Accept connection from 127.0.0.1:50372." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:56-07:00" level=info msg="Upstream connection to 127.0.0.1:42571." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:56-07:00" level=info msg="Peer reconnected." reconnected="peer(addr=127.0.0.1:42907)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=info msg="Peer reconnected." reconnected="peer(addr=127.0.0.1:40099)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:56-07:00" level=error msg="Failed to accept: accept tcp4 127.0.0.1:40099: use of closed network connection." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:56-07:00" level=info msg="Proxy stopped." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:57-07:00" level=warning msg="Failed health check: <nil> (rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: <nil>)." checked="peer(addr=127.0.0.1:40099)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:57-07:00" level=info msg="Proxy started." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:57-07:00" level=info msg="Accept connection from 127.0.0.1:50386." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:57-07:00" level=info msg="Upstream connection to 127.0.0.1:42571." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=info msg="Accept connection from 127.0.0.1:50390." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=info msg="Upstream connection to 127.0.0.1:42571." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=info msg="Peer reconnected." reconnected="peer(addr=127.0.0.1:40099)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=error msg="Failed to accept: accept tcp4 127.0.0.1:40099: use of closed network connection." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=debug msg="request received" args="[test]" peer="127.0.0.1:42571" request=Command test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=debug msg="completed OK" args="[test]" peer="127.0.0.1:42571" request=Command test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=debug msg="Run [\"test\"]." seq=1 test=AgentGroupReconnects trace.component=rpc
time="2020-05-20T14:37:58-07:00" level=info msg="\"test output\"" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=debug msg=Completed. exit=0 seq=1 test=AgentGroupReconnects trace.component=rpc
time="2020-05-20T14:37:58-07:00" level=info msg="Proxy stopped." proxy="netlink(local=127.0.0.1:40099, upstream=127.0.0.1:42571)" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=info msg="Reconnect loop closing." reconnected="peer(addr=127.0.0.1:40099)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:40099" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:42907),peer(addr=127.0.0.1:40099)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:42907" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Reconnect loop closing." reconnected="peer(addr=127.0.0.1:42907)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=debug msg=PeerLeave. req="PeerLeaveRequest(addr=127.0.0.1:40099, config=)" server="127.0.0.1:41119" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=info msg="Reconnect loop closing." peer="127.0.0.1:42571" reconnected="peer(addr=127.0.0.1:40099->server=127.0.0.1:41119)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:41119)" peer="127.0.0.1:42571" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Server stopped." error="<nil>" peer="127.0.0.1:42571" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:41119" peer="127.0.0.1:42571" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=debug msg=PeerLeave. req="PeerLeaveRequest(addr=127.0.0.1:42907, config=)" server="127.0.0.1:41119" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=info msg="Reconnect loop closing." peer="127.0.0.1:42907" reconnected="peer(addr=127.0.0.1:42907->server=127.0.0.1:41119)" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:41119)" peer="127.0.0.1:42907" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Server stopped." error="<nil>" peer="127.0.0.1:42907" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:41119" peer="127.0.0.1:42907" test=AgentGroupReconnects trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Server stopped." error="<nil>" server="127.0.0.1:41119" test=AgentGroupReconnects
time="2020-05-20T14:37:58-07:00" level=info msg="Proxy started." proxy="netlink(local=127.0.0.1:40627, upstream=127.0.0.1:36413)" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:37:58-07:00" level=info msg=Listening. addr="127.0.0.1:37355" server="127.0.0.1:37355" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:37:58-07:00" level=info msg=Listening. addr="127.0.0.1:36413" peer="127.0.0.1:36413" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:37:58-07:00" level=info msg=Monitoring. monitored="127.0.0.1:37355" peer="127.0.0.1:36413" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg=Reconnecting peer="127.0.0.1:36413" reconnected="peer(addr=127.0.0.1:40627->server=127.0.0.1:37355)" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:37355)" peer="127.0.0.1:36413" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:37:58-07:00" level=debug msg=PeerJoin. req="PeerJoinRequest(addr=127.0.0.1:40627, config=)" server="127.0.0.1:37355" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:37:58-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:40627)" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg=Monitoring. monitored="127.0.0.1:40627" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg=Reconnecting reconnected="peer(addr=127.0.0.1:40627)" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Accept connection from 127.0.0.1:33374." proxy="netlink(local=127.0.0.1:40627, upstream=127.0.0.1:36413)" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:37:58-07:00" level=info msg="Peer reconnected." peer="127.0.0.1:36413" reconnected="peer(addr=127.0.0.1:40627->server=127.0.0.1:37355)" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Upstream connection to 127.0.0.1:36413." proxy="netlink(local=127.0.0.1:40627, upstream=127.0.0.1:36413)" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:37:58-07:00" level=info msg="Dropped update notification for watchEvent(peer(addr=127.0.0.1:40627->server=127.0.0.1:37355), client=&{0xc00019c218 0xc00019c238 0xc0003b2900}, error=<nil>)." health.checker="peer(addr=127.0.0.1:37355)" peer="127.0.0.1:36413" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Peer reconnected." reconnected="peer(addr=127.0.0.1:40627)" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:37:58-07:00" level=info msg="Reconnect response: watchEvent(peer(addr=127.0.0.1:40627), client=&{0xc0000fa3e0 0xc0000fa3e8 0xc00063a900}, error=<nil>)." test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:37:58-07:00" level=error msg="Failed to accept: accept tcp4 127.0.0.1:40627: use of closed network connection." proxy="netlink(local=127.0.0.1:40627, upstream=127.0.0.1:36413)" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:37:58-07:00" level=info msg="Proxy stopped." proxy="netlink(local=127.0.0.1:40627, upstream=127.0.0.1:36413)" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:37:59-07:00" level=warning msg="Failed health check: <nil> (rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:40627: connect: connection refused\")." checked="peer(addr=127.0.0.1:40627)" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=warning msg="All attempts failed." error="context deadline exceeded"
time="2020-05-20T14:38:00-07:00" level=warning msg="Failed to reconnect: \nERROR REPORT:\nOriginal Error: context.deadlineExceededError context deadline exceeded\nStack Trace:\n\t/code/go/src/github.com/gravitational/gravity/lib/rpc/server/peer.go:327 github.com/gravitational/gravity/lib/rpc/server.newClient\n\t/code/go/src/github.com/gravitational/gravity/lib/rpc/server/peer.go:300 github.com/gravitational/gravity/lib/rpc/server.remotePeer.Reconnect\n\t/code/go/src/github.com/gravitational/gravity/lib/rpc/server/peers.go:221 github.com/gravitational/gravity/lib/rpc/server.(*peers).reconnectPeer.func1\n\t/code/go/src/github.com/gravitational/gravity/lib/utils/retry.go:235 github.com/gravitational/gravity/lib/utils.RetryWithInterval.func1\n\t/code/go/src/github.com/gravitational/gravity/vendor/github.com/cenkalti/backoff/retry.go:37 github.com/gravitational/gravity/vendor/github.com/cenkalti/backoff.RetryNotify\n\t/code/go/src/github.com/gravitational/gravity/lib/utils/retry.go:234 github.com/gravitational/gravity/lib/utils.RetryWithInterval\n\t/code/go/src/github.com/gravitational/gravity/lib/rpc/server/peers.go:220 github.com/gravitational/gravity/lib/rpc/server.(*peers).reconnectPeer\n\t/usr/local/go/src/runtime/asm_amd64.s:1337 runtime.goexit\nUser Message: context deadline exceeded." monitored="127.0.0.1:40627" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:40627" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Reconnect failure response: watchEvent(peer(addr=127.0.0.1:40627), client=<nil>, error=context deadline exceeded)." test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:38:00-07:00" level=info msg="Reconnect loop closing." reconnected="peer(addr=127.0.0.1:40627)" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:40627)" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=debug msg=PeerLeave. req="PeerLeaveRequest(addr=127.0.0.1:40627, config=)" server="127.0.0.1:37355" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:38:00-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:37355)" peer="127.0.0.1:36413" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:37355" peer="127.0.0.1:36413" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Reconnect loop closing." peer="127.0.0.1:36413" reconnected="peer(addr=127.0.0.1:40627->server=127.0.0.1:37355)" test=AgentGroupRemovesPeerItCannotReconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Server stopped." error="<nil>" peer="127.0.0.1:36413" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:38:00-07:00" level=info msg="Server stopped." error="<nil>" server="127.0.0.1:37355" test=AgentGroupRemovesPeerItCannotReconnect
time="2020-05-20T14:38:00-07:00" level=info msg=Listening. addr="127.0.0.1:34861" server="127.0.0.1:34861" test=AgentsConnectToController
time="2020-05-20T14:38:00-07:00" level=info msg=Listening. addr="127.0.0.1:40571" peer="127.0.0.1:40571" test=AgentsConnectToController
time="2020-05-20T14:38:00-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:34861)" peer="127.0.0.1:40571" test=AgentsConnectToController trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg=Reconnecting peer="127.0.0.1:40571" reconnected="peer(addr=127.0.0.1:40571->server=127.0.0.1:34861)" test=AgentsConnectToController trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg=Monitoring. monitored="127.0.0.1:34861" peer="127.0.0.1:40571" test=AgentsConnectToController trace.component=peers
time="2020-05-20T14:38:00-07:00" level=debug msg=PeerJoin. req="PeerJoinRequest(addr=127.0.0.1:40571, config=)" server="127.0.0.1:34861" test=AgentsConnectToController
time="2020-05-20T14:38:00-07:00" level=info msg="Peer reconnected." peer="127.0.0.1:40571" reconnected="peer(addr=127.0.0.1:40571->server=127.0.0.1:34861)" test=AgentsConnectToController trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Dropped update notification for watchEvent(peer(addr=127.0.0.1:40571->server=127.0.0.1:34861), client=&{0xc00019c4c8 0xc00019c4d0 0xc0003b3500}, error=<nil>)." health.checker="peer(addr=127.0.0.1:34861)" peer="127.0.0.1:40571" test=AgentsConnectToController trace.component=peers
time="2020-05-20T14:38:00-07:00" level=debug msg=PeerLeave. req="PeerLeaveRequest(addr=127.0.0.1:40571, config=)" server="127.0.0.1:34861" test=AgentsConnectToController
time="2020-05-20T14:38:00-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:34861)" peer="127.0.0.1:40571" test=AgentsConnectToController trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:34861" peer="127.0.0.1:40571" test=AgentsConnectToController trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Reconnect loop closing." peer="127.0.0.1:40571" reconnected="peer(addr=127.0.0.1:40571->server=127.0.0.1:34861)" test=AgentsConnectToController trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Server stopped." error="<nil>" peer="127.0.0.1:40571" test=AgentsConnectToController
time="2020-05-20T14:38:00-07:00" level=info msg="Server stopped." error="<nil>" server="127.0.0.1:34861" test=AgentsConnectToController
time="2020-05-20T14:38:00-07:00" level=info msg=Listening. addr="127.0.0.1:36785" server="127.0.0.1:36785" test=ClientExecutesCommandsRemotely
time="2020-05-20T14:38:00-07:00" level=debug msg="request received" args="[test]" request=Command server="127.0.0.1:36785" test=ClientExecutesCommandsRemotely
time="2020-05-20T14:38:00-07:00" level=debug msg="completed OK" args="[test]" request=Command server="127.0.0.1:36785" test=ClientExecutesCommandsRemotely
time="2020-05-20T14:38:00-07:00" level=debug msg="Run [\"test\"]." seq=1 trace.component=rpc
time="2020-05-20T14:38:00-07:00" level=info msg="\"server output\"" trace.component=client
time="2020-05-20T14:38:00-07:00" level=debug msg=Completed. exit=0 seq=1 trace.component=rpc
time="2020-05-20T14:38:00-07:00" level=info msg=Shutdown. server="127.0.0.1:36785" test=ClientExecutesCommandsRemotely
time="2020-05-20T14:38:00-07:00" level=info msg="Server stopped." error="<nil>" server="127.0.0.1:36785" test=ClientExecutesCommandsRemotely
time="2020-05-20T14:38:00-07:00" level=info msg=Listening. addr="127.0.0.1:43119" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg=Listening. addr="127.0.0.1:40557" server="127.0.0.1:40557" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=info msg=Listening. addr="127.0.0.1:34813" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg=Monitoring. monitored="127.0.0.1:40557" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg=Reconnecting reconnected="peer(addr=127.0.0.1:43119->server=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg=Monitoring. monitored="127.0.0.1:40557" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg=Reconnecting reconnected="peer(addr=127.0.0.1:34813->server=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=debug msg=PeerJoin. req="PeerJoinRequest(addr=127.0.0.1:34813, config=)" server="127.0.0.1:40557" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=debug msg=PeerJoin. req="PeerJoinRequest(addr=127.0.0.1:43119, config=)" server="127.0.0.1:40557" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=info msg="Peer reconnected." reconnected="peer(addr=127.0.0.1:43119->server=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Dropped update notification for watchEvent(peer(addr=127.0.0.1:34813->server=127.0.0.1:40557), client=&{0xc00019c108 0xc00019c138 0xc0006dbb00}, error=<nil>)." health.checker="peer(addr=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Peer reconnected." reconnected="peer(addr=127.0.0.1:34813->server=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Dropped update notification for watchEvent(peer(addr=127.0.0.1:43119->server=127.0.0.1:40557), client=&{0xc0000fa178 0xc0000fa190 0xc0006db800}, error=<nil>)." health.checker="peer(addr=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=debug msg=PeerLeave. req="PeerLeaveRequest(addr=127.0.0.1:34813, config=)" server="127.0.0.1:40557" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Reconnect loop closing." reconnected="peer(addr=127.0.0.1:34813->server=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:40557" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Server stopped." error="<nil>" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=debug msg=PeerLeave. req="PeerLeaveRequest(addr=127.0.0.1:43119, config=)" server="127.0.0.1:40557" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=info msg="Reconnect loop closing." reconnected="peer(addr=127.0.0.1:43119->server=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:40557)" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:40557" test=PeerDisconnect trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Server stopped." error="<nil>" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=debug msg=PeerLeave. req="PeerLeaveRequest(addr=127.0.0.1:34813, config=)" server="127.0.0.1:40557" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=info msg="Server stopped." error="<nil>" server="127.0.0.1:40557" test=PeerDisconnect
time="2020-05-20T14:38:00-07:00" level=info msg="Proxy started." proxy="netlink(local=127.0.0.1:43469, upstream=127.0.0.1:39643)" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=info msg=Listening. addr="127.0.0.1:39643" server="127.0.0.1:39643" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=info msg=Listening. addr="127.0.0.1:40421" peer="127.0.0.1:40421" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=info msg=Monitoring. monitored="127.0.0.1:43469" peer="127.0.0.1:40421" test=PeerReconnects trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:43469)" peer="127.0.0.1:40421" test=PeerReconnects trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg=Reconnecting peer="127.0.0.1:40421" reconnected="peer(addr=127.0.0.1:40421->server=127.0.0.1:43469)" test=PeerReconnects trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Accept connection from 127.0.0.1:50724." proxy="netlink(local=127.0.0.1:43469, upstream=127.0.0.1:39643)" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=info msg="Upstream connection to 127.0.0.1:39643." proxy="netlink(local=127.0.0.1:43469, upstream=127.0.0.1:39643)" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=debug msg=PeerJoin. req="PeerJoinRequest(addr=127.0.0.1:40421, config=)" server="127.0.0.1:39643" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=info msg="Peer reconnected." peer="127.0.0.1:40421" reconnected="peer(addr=127.0.0.1:40421->server=127.0.0.1:43469)" test=PeerReconnects trace.component=peers
time="2020-05-20T14:38:00-07:00" level=error msg="Failed to accept: accept tcp4 127.0.0.1:43469: use of closed network connection." proxy="netlink(local=127.0.0.1:43469, upstream=127.0.0.1:39643)" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=info msg="Proxy stopped." proxy="netlink(local=127.0.0.1:43469, upstream=127.0.0.1:39643)" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=info msg="Proxy started." proxy="netlink(local=127.0.0.1:43469, upstream=127.0.0.1:39643)" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=warning msg="Failed health check: <nil> (rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:43469: connect: connection refused\")." checked="peer(addr=127.0.0.1:40421->server=127.0.0.1:43469)" peer="127.0.0.1:40421" test=PeerReconnects trace.component=peers
time="2020-05-20T14:38:00-07:00" level=info msg="Accept connection from 127.0.0.1:50730." proxy="netlink(local=127.0.0.1:43469, upstream=127.0.0.1:39643)" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=info msg="Upstream connection to 127.0.0.1:39643." proxy="netlink(local=127.0.0.1:43469, upstream=127.0.0.1:39643)" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=debug msg=PeerJoin. req="PeerJoinRequest(addr=127.0.0.1:40421, config=)" server="127.0.0.1:39643" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=info msg="Peer reconnected." peer="127.0.0.1:40421" reconnected="peer(addr=127.0.0.1:40421->server=127.0.0.1:43469)" test=PeerReconnects trace.component=peers
time="2020-05-20T14:38:00-07:00" level=error msg="Failed to accept: accept tcp4 127.0.0.1:43469: use of closed network connection." proxy="netlink(local=127.0.0.1:43469, upstream=127.0.0.1:39643)" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=info msg="Proxy stopped." proxy="netlink(local=127.0.0.1:43469, upstream=127.0.0.1:39643)" test=PeerReconnects
time="2020-05-20T14:38:00-07:00" level=warning msg="Failed health check: <nil> (rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:43469: connect: connection refused\")." checked="peer(addr=127.0.0.1:40421->server=127.0.0.1:43469)" peer="127.0.0.1:40421" test=PeerReconnects trace.component=peers
time="2020-05-20T14:38:02-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:43469" peer="127.0.0.1:40421" test=PeerReconnects trace.component=peers
time="2020-05-20T14:38:02-07:00" level=warning msg="All attempts failed." error="context canceled"
time="2020-05-20T14:38:02-07:00" level=info msg="Reconnect loop closing." peer="127.0.0.1:40421" reconnected="peer(addr=127.0.0.1:40421->server=127.0.0.1:43469)" test=PeerReconnects trace.component=peers
time="2020-05-20T14:38:02-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:43469)" peer="127.0.0.1:40421" test=PeerReconnects trace.component=peers
time="2020-05-20T14:38:02-07:00" level=info msg="Server stopped." error="<nil>" server="127.0.0.1:39643" test=PeerReconnects
time="2020-05-20T14:38:02-07:00" level=info msg=Listening. addr="127.0.0.1:33593" server="127.0.0.1:33593" test=QueriesSystemInfo
time="2020-05-20T14:38:02-07:00" level=info msg="Server stopped." error="<nil>" server="127.0.0.1:33593" test=QueriesSystemInfo
time="2020-05-20T14:38:02-07:00" level=info msg=Listening. addr="127.0.0.1:37159" test=RejectsPeer
time="2020-05-20T14:38:02-07:00" level=info msg="Monitoring peers." health.checker="peer(addr=127.0.0.1:38111)" test=RejectsPeer trace.component=peers
time="2020-05-20T14:38:02-07:00" level=info msg=Monitoring. monitored="127.0.0.1:38111" test=RejectsPeer trace.component=peers
time="2020-05-20T14:38:02-07:00" level=info msg=Listening. addr="127.0.0.1:38111" server="127.0.0.1:38111" test=RejectsPeer
time="2020-05-20T14:38:02-07:00" level=info msg=Reconnecting reconnected="peer(addr=127.0.0.1:37159->server=127.0.0.1:38111)" test=RejectsPeer trace.component=peers
time="2020-05-20T14:38:02-07:00" level=debug msg=PeerJoin. req="PeerJoinRequest(addr=127.0.0.1:37159, config=)" server="127.0.0.1:38111" test=RejectsPeer
time="2020-05-20T14:38:02-07:00" level=warning msg="All attempts failed." error="rpc error: code = Unknown desc = peer not authorized"
time="2020-05-20T14:38:02-07:00" level=warning msg="Failed to reconnect: \nERROR REPORT:\nOriginal Error: *status.statusError rpc error: code = Unknown desc = peer not authorized\nStack Trace:\n\t/code/go/src/github.com/gravitational/gravity/lib/utils/retry.go:248 github.com/gravitational/gravity/lib/utils.RetryWithInterval\n\t/code/go/src/github.com/gravitational/gravity/lib/rpc/server/peers.go:220 github.com/gravitational/gravity/lib/rpc/server.(*peers).reconnectPeer\n\t/usr/local/go/src/runtime/asm_amd64.s:1337 runtime.goexit\nUser Message: rpc error: code = Unknown desc = peer not authorized." monitored="127.0.0.1:38111" test=RejectsPeer trace.component=peers
time="2020-05-20T14:38:02-07:00" level=info msg="Monitoring loop closing." monitored="127.0.0.1:38111" test=RejectsPeer trace.component=peers
time="2020-05-20T14:38:02-07:00" level=info msg="Reconnect loop closing." reconnected="peer(addr=127.0.0.1:37159->server=127.0.0.1:38111)" test=RejectsPeer trace.component=peers
time="2020-05-20T14:38:02-07:00" level=info msg="Health checker loop closing." health.checker="peer(addr=127.0.0.1:38111)" test=RejectsPeer trace.component=peers
time="2020-05-20T14:38:02-07:00" level=info msg="Server stopped." error="<nil>" test=RejectsPeer
time="2020-05-20T14:38:02-07:00" level=info msg="Server stopped." error="<nil>" server="127.0.0.1:38111" test=RejectsPeer
time="2020-05-20T14:38:02-07:00" level=info msg=Listening. addr="127.0.0.1:43979" server="127.0.0.1:43979" test=ServerReportsHealth
time="2020-05-20T14:38:02-07:00" level=info msg="Server stopped." error="<nil>" server="127.0.0.1:43979" test=ServerReportsHealth
time="2020-05-20T14:38:02-07:00" level=info msg=Listening. addr="127.0.0.1:34057" server="127.0.0.1:34057" test=WaitsUntilAgentShutsDown
OK: 13 passed
--- PASS: TestServer (5.47s)
time="2020-05-20T14:38:02-07:00" level=info msg="Server stopped." error="grpc: the server has been stopped" server="127.0.0.1:34057" test=WaitsUntilAgentShutsDown
PASS
ok  	github.com/gravitational/gravity/lib/rpc/server	(cached)
➜  gravity git:(dmitri/5.5.x/1091-agent) echo $?
0

@r0mant r0mant merged commit adce348 into version/5.5.x May 20, 2020
@r0mant r0mant deleted the dmitri/5.5.x/1091-agent branch May 20, 2020 21:40
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Reviewers

@r0mant r0mant r0mant approved these changes

@knisbet knisbet knisbet approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@a-palchikov @r0mant @knisbet