packetdrill: more tests failing due to packets arriving later than expected

[matttbe]

My CI reported this error twice in a row:

# dss_fin_retrans_close_wait.pkt:17: error handling packet: timing error: expected outbound packet at 0.010053 sec but happened at 0.299989 sec; tolerance 0.200000 sec

The public CI didn't report this error recently but similar ones:

# dss_fin_retrans_close_wait.pkt:28: error handling packet: timing error: expected outbound packet at 0.840860 sec but happened at 1.042545 sec; tolerance 0.200000 sec
# dss_fin_retrans_established.pkt:22: error handling packet: timing error: expected outbound packet at 0.840663 sec but happened at 1.044058 sec; tolerance 0.200000 sec
# add_addr_retry_v4.pkt:22: error handling packet: timing error: expected outbound packet at 3.200581 sec but happened at 2.457930 sec; tolerance 0.400000 sec
# add_addr_retry_v4.pkt:22: error handling packet: timing error: expected outbound packet at 3.223055 sec but happened at 2.341809 sec; tolerance 0.400000 sec

https://cirrus-ci.com/task/4632164236001280
https://cirrus-ci.com/task/5272829749886976
https://cirrus-ci.com/task/4735947389534208

Just unlucky or a behaviour change / regression?

[matttbe]

More samples from this WE:

Build 311:

 # dss_fin_retrans_close_wait.pkt:27: error handling packet: timing error: expected outbound packet at 0.520166 sec but happened at 0.960162 sec; tolerance 0.200000 sec
 # dss_fin_retrans_close_wait.pkt:26: error handling packet: timing error: expected outbound packet at 0.210819 sec but happened at 0.641166 sec; tolerance 0.200000 sec
 # dss_fin_retrans_established.pkt:21: error handling packet: timing error: expected outbound packet at 0.520297 sec but happened at 0.959895 sec; tolerance 0.200000 sec
 # dss_fin_retrans_close_wait.pkt:27: error handling packet: timing error: expected outbound packet at 0.420386 sec but happened at 0.660316 sec; tolerance 0.200000 sec
 # dss_fin_retrans_established.pkt:21: error handling packet: timing error: expected outbound packet at 0.570491 sec but happened at 0.773001 sec; tolerance 0.200000 sec

Build 312:

 # add_addr6_server.pkt:16: timing error: expected inbound packet at 0.500314 sec but happened at 0.789865 sec; tolerance 0.200000 sec
 # dss_fin_retrans_close_wait.pkt:26: error handling packet: timing error: expected outbound packet at 0.210895 sec but happened at 0.480059 sec; tolerance 0.200000 sec
 # dss_fin_retrans_close_wait.pkt:26: error handling packet: timing error: expected outbound packet at 0.210838 sec but happened at 0.470189 sec; tolerance 0.200000 sec
 # dss_fin_retrans_established.pkt:20: error handling packet: timing error: expected outbound packet at 0.212147 sec but happened at 0.482149 sec; tolerance 0.200000 sec

Please note that all the others tests on my CI are passing, only these packetdrill tests are failing which is suspect.

[matttbe]

Please note that in my VM, I was able to reproduce it but after almost 300 attempts... Maybe an issue linked to my CI?

[dcaratti]

just happened happened also in my VM, on the same test cases.

[matttbe]

The ADD_ADDR tests are going to be fixed by #312.

I don't think I saw the DSS failures recently.

I suggest to close this issue, we can still re-open it if we still see these issues.