https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/21536/pull-ci-openshift-origin-master-e2e-aws/1095 looks like it was sufficient to find the cause of some of the timeout / API errors.
At 17:56:13 we got a notification that a request timed out. The timeout was because the etcd leader stepped down (due to failing too many heart beats in a row?) and then the inflight request from the client times out.
Leader stepping down:
2018-11-26 17:56:03.975261 W | etcdserver: failed to send out heartbeat on time (exceeded the 100ms timeout for 46.873965ms)
2018-11-26 17:56:03.975324 W | etcdserver: server is likely overloaded
2018-11-26 17:56:03.975366 W | etcdserver: failed to send out heartbeat on time (exceeded the 100ms timeout for 47.078353ms)
2018-11-26 17:56:03.975426 W | etcdserver: server is likely overloaded
2018-11-26 17:56:08.000690 W | etcdserver: failed to send out heartbeat on time (exceeded the 100ms timeout for 64.57495ms)
2018-11-26 17:56:08.000716 W | etcdserver: server is likely overloaded
2018-11-26 17:56:08.000723 W | etcdserver: failed to send out heartbeat on time (exceeded the 100ms timeout for 64.612207ms)
2018-11-26 17:56:08.000728 W | etcdserver: server is likely overloaded
2018-11-26 17:56:08.806389 W | etcdserver: apply entries took too long [103.599077ms for 1 entries]
2018-11-26 17:56:08.806422 W | etcdserver: avoid queries with large range/delete range!
2018-11-26 17:56:11.006232 I | raft: 579f9328acf2e245 [term: 12] received a MsgApp message with higher term from b6e62fef46993eff [term: 13]
2018-11-26 17:56:11.006336 I | raft: 579f9328acf2e245 became follower at term 13
2018-11-26 17:56:11.006387 I | raft: found conflict at index 47160 [existing term: 12, conflicting term: 13]
2018-11-26 17:56:11.006424 I | raft: replace the unstable entries from index 47160
2018-11-26 17:56:11.006459 I | raft: raft.node: 579f9328acf2e245 changed leader from 579f9328acf2e245 to b6e62fef46993eff at term 13
2018-11-26 17:56:11.006686 W | etcdserver: failed to send out heartbeat on time (exceeded the 100ms timeout for 1.376888958s)
2018-11-26 17:56:11.006744 W | etcdserver: server is likely overloaded
2018-11-26 17:56:11.006783 W | etcdserver: failed to send out heartbeat on time (exceeded the 100ms timeout for 1.377002135s)
2018-11-26 17:56:11.024165 W | etcdserver: server is likely overloaded
2018-11-26 17:56:11.025909 I | raft: 579f9328acf2e245 [term: 13] ignored a MsgHeartbeatResp message with lower term from b6e62fef46993eff [term: 12]
New leader
2018-11-26 17:56:10.859109 I | raft: b6e62fef46993eff is starting a new election at term 12
2018-11-26 17:56:10.859143 I | raft: b6e62fef46993eff became candidate at term 13
2018-11-26 17:56:10.859155 I | raft: b6e62fef46993eff received MsgVoteResp from b6e62fef46993eff at term 13
2018-11-26 17:56:10.859166 I | raft: b6e62fef46993eff [logterm: 12, index: 47159] sent MsgVote request to 579f9328acf2e245 at term 13
2018-11-26 17:56:10.859173 I | raft: b6e62fef46993eff [logterm: 12, index: 47159] sent MsgVote request to a39f7c9bbad46d94 at term 13
2018-11-26 17:56:10.859181 I | raft: raft.node: b6e62fef46993eff lost leader 579f9328acf2e245 at term 13
2018-11-26 17:56:10.864506 I | raft: b6e62fef46993eff received MsgVoteResp from a39f7c9bbad46d94 at term 13
2018-11-26 17:56:10.864523 I | raft: b6e62fef46993eff [quorum:2] has received 2 MsgVoteResp votes and 0 vote rejections
2018-11-26 17:56:10.864536 I | raft: b6e62fef46993eff became leader at term 13
2018-11-26 17:56:10.864547 I | raft: raft.node: b6e62fef46993eff elected leader b6e62fef46993eff at term 13
2018-11-26 17:56:16.429974 W | etcdserver: timed out waiting for read index response
2018-11-26 17:56:17.835339 I | mvcc: store.index: compact 37875
2018-11-26 17:56:17.970906 I | mvcc: finished scheduled compaction at 37875 (took 127.026268ms)
Other follower:
2018-11-26 17:56:10.862098 I | raft: a39f7c9bbad46d94 [term: 12] received a MsgVote message with higher term from b6e62fef46993eff [term: 13]
2018-11-26 17:56:10.862144 I | raft: a39f7c9bbad46d94 became follower at term 13
2018-11-26 17:56:10.862157 I | raft: a39f7c9bbad46d94 [logterm: 12, index: 47159, vote: 0] cast MsgVote for b6e62fef46993eff [logterm: 12, index: 47159] at term 13
2018-11-26 17:56:10.862165 I | raft: raft.node: a39f7c9bbad46d94 lost leader 579f9328acf2e245 at term 13
2018-11-26 17:56:10.865751 I | raft: raft.node: a39f7c9bbad46d94 elected leader b6e62fef46993eff at term 13
2018-11-26 17:56:16.430174 W | etcdserver: timed out waiting for read index response
2018-11-26 17:56:17.836370 I | mvcc: store.index: compact 37875
2018-11-26 17:56:17.996543 I | mvcc: finished scheduled compaction at 37875 (took 154.77676ms)
This was reported back to this client as a 504 server timeout error (which is correct).
In the logs preceding the new election I see a bunch of:
2018-11-26 17:56:03.975261 W | etcdserver: failed to send out heartbeat on time (exceeded the 100ms timeout for 46.873965ms)
The masters could be busy enough that they can't chat, but that seems strange.
Will look for this on other failing runs.
https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/21536/pull-ci-openshift-origin-master-e2e-aws/1095 looks like it was sufficient to find the cause of some of the timeout / API errors.
At 17:56:13 we got a notification that a request timed out. The timeout was because the etcd leader stepped down (due to failing too many heart beats in a row?) and then the inflight request from the client times out.
Leader stepping down:
New leader
Other follower:
This was reported back to this client as a 504 server timeout error (which is correct).
In the logs preceding the new election I see a bunch of:
The masters could be busy enough that they can't chat, but that seems strange.
Will look for this on other failing runs.