Flaky tests on travis

[nabeken]

2014/11/12 19:30:16 [DEBUG] delayd: Got entry:  {2014-11-12 19:30:17.052430821 +0900 JST delayd-test [77 101 115 115 97 103 101 32 49] key1 0xc2080d15c0}
2014/11/12 19:30:16 [DEBUG] delayd: [0 0 189 151 121 47 86 89 64 59 129 159 219 107 75 132 211 13]
2014/11/12 19:30:16 [DEBUG] delayd: Applying add command
2014/11/12 19:30:16 [DEBUG] delayd: Entry has key:  key1
2014/11/12 19:30:16 [DEBUG] delayd: got time 2014-11-12 19:30:17.052430821 +0900 JST
2014/11/12 19:30:16 [DEBUG] delayd: Timer reset to 2014-11-12 19:30:17.052430821 +0900 JST
2014/11/12 19:30:16 [DEBUG] delayd: Got entry:  {2014-11-12 19:30:16.062705387 +0900 JST delayd-test [77 101 115 115 97 103 101 32 50] key2 0xc2080d19b0}
2014/11/12 19:30:16 [DEBUG] delayd: [0 0 247 151 250 190 222 38 77 156 140 96 64 110 48 42 173 248]
2014/11/12 19:30:16 [DEBUG] delayd: Applying add command
2014/11/12 19:30:16 [DEBUG] delayd: Entry has key:  key2
2014/11/12 19:30:16 [DEBUG] delayd: got time 2014-11-12 19:30:16.062705387 +0900 JST
2014/11/12 19:30:16 [DEBUG] delayd: Timer reset to 2014-11-12 19:30:16.06527319 +0900 JST
2014/11/12 19:30:16 [DEBUG] delayd: Got entry:  {2014-11-12 19:30:16.564803561 +0900 JST delayd-test [77 101 115 115 97 103 101 32 51] key3 0xc2080a80c0}
2014/11/12 19:30:16 [DEBUG] delayd: [0 0 161 34 124 145 72 195 79 216 133 96 158 70 89 98 92 191]
2014/11/12 19:30:16 [DEBUG] delayd: Looking for:  2014-11-12 19:30:16.065466894 +0900 JST 1415788216065466894
2014/11/12 19:30:16 [INFO] delayd: Sending 1 entries
2014/11/12 19:30:16 [DEBUG] delayd: Applying add command
2014/11/12 19:30:16 [DEBUG] delayd: Entry has key:  key3
2014/11/12 19:30:16 [DEBUG] delayd: got time 2014-11-12 19:30:16.062705387 +0900 JST
2014/11/12 19:30:16 [DEBUG] delayd: Timer reset to 2014-11-12 19:30:16.066108956 +0900 JST
2014/11/12 19:30:16 [DEBUG] delayd: Applying rm command
2014/11/12 19:30:16 [DEBUG] delayd: got time 2014-11-12 19:30:16.564803561 +0900 JST
2014/11/12 19:30:16 [DEBUG] delayd: syncing raft after send.
2014/11/12 19:30:16 [DEBUG] delayd: synced raft after send.
2014/11/12 19:30:16 [DEBUG] delayd: Looking for:  2014-11-12 19:30:16.066189439 +0900 JST 1415788216066189439
2014/11/12 19:30:16 [INFO] delayd: Sending 0 entries
2014/11/12 19:30:16 [DEBUG] delayd: syncing raft after send.
2014/11/12 19:30:16 [DEBUG] delayd: synced raft after send.
2014/11/12 19:30:16 [INFO] delayd: client: written Message 2

I think something is wrong with resetting timer. In production, timer receives requests continuously. If timer is missing a timing, a following request resets a timer so it is not a problem. In testing, only 3 requests are sent. If timer is missing a timing, no more action is performed.

[nabeken]

captured.

2014/11/13 11:57:54 [DEBUG] delayd: Timer reset to 2014-11-13 11:57:54.554543045 +0900 JST
2014/11/13 11:57:54 [DEBUG] delayd: Timer reset: -11.153us

timer.go abuses time.Now(). Entering to Reset() is synced with sync.Mutex but time.Now() is not synced. This allows the timer to set negative duration then timer is stopped.

[nabeken]

solutions

• Sync time.Now()
• To take a safety precaution, we also launch a ticker every 3 seconds

[nabeken]

2014/11/13 14:03:31 [DEBUG] delayd: Timer reset to 2014-11-13 14:03:31.950286291 +0900 JST
2014/11/13 14:03:31 [DEBUG] delayd: Timer reset: 0

If time.Now() equals to nextTime, a timer is stopped. Take care of this situation.