Rewrite test_logging_throttle tests #167

jpsamper2009 · 2019-06-28T21:40:03Z

The old test is basically trying to write logs, dropping the ones that come too often. In this case, it is writing 10 logs every 30 ms, but only allowing one every 50 ms:

R = Received
T = Throttled
0 <-- 30 ms --> 1 <-- 30 ms --> 2 <-- 30 ms --> 3...
R               T               R               T 
|----- 50 ms ------------>      |----- 50 ms ------------>

However, if the 30 ms sleep jitters and/or the RCUTILS call takes too long, then the a log that should have been dropped, doesn't actually get dropped:

R = Received
T = Throttled
0 <-- RCUTILS_LOG -> <-- 30 ms --> 1 <-- 30 ms --> 2 <-- 30 ms --> 3...
R                                  R <--- Should be throttled 
|----- 50 ms ------------>         |----- 50 ms ------------>

This PR changes the test in a way that it is not subject to timing discrepancies:

R = Received
T = Throttled
first  < ~5 ms > other < ~5 ms > other < ~5 ms > ... < ~5 ms > other
R                T               T             T ... T         R      
|----- 200 ms --------------------------------------------->

In this case, we are testing that after receiving the first log call, no more logs are written until
the throttle time (or longer) has elapsed. This test is more robust than the old one because it doesn't make an assumption about how many logs get throttled to get the number received, but
instead checks that the second log is received only after we are certain that the throttle timeout has occurred