Inconsistency in tsung.log

[tisba]

I recently observed that we have snapshots in our tsung.log that have 0 reported requests for this 10 sec segment, but reported http status codes.

A slightly simplified example snapshot looks like this:

# stats: dump at 1530892859
stats: users 20 20
stats: session 0 0 0 157.292 157.292 157.292 1
stats: users_count 0 21
stats: finish_users_count 0 1
stats: request 0 0 0 3049.718 52.337 367.2719321428573 1120
stats: connect 1 125.53 0.0 150.33 5.7 82.37184615384614 39
stats: page 0 0 0 3049.718 52.337 447.2258141304348 920
stats: 302 0 481
stats: 200 1 640
stats: size_rcv 0 9656076
stats: size_sent 1141 876536
stats: connected 1 20

This was produced by tsung build from 68e509fedc.

Status codes are reported to ts_mon here https://github.com/processone/tsung/blob/68e509fedc703a7a2a444c90a8f2df882d517d8a/src/tsung/ts_http_common.erl#L615 in ts_http_common:parse_status/2 and request here https://github.com/processone/tsung/blob/68e509fedc703a7a2a444c90a8f2df882d517d8a/src/tsung/ts_mon_cache.erl#L165 in ts_mon_cache:handle.

Any idea how we could prevent this to make the result data consistent, @nniclausse?

[tisba]

@nniclausse do you have any idea how to track this issue down? I haven't figured out a good way to reliably reproduce this yet unfortunately :/

[tisba]

Ping @nniclausse. Any idea what is going on here?

[nniclausse]

One possibility is to receive the http status just before the stats are dumped to the disk; the end of the request car occur a few msecs after the status is known, and therefore logged 10 sec later

[tisba]

Can/should we change this behaviour? Like counting the request only of the the status is known (or we know that we cannot determine the status)?