Sometimes json data is mixed up with other output from fortio

[TenSt]

Note: was observed on small load tests: duration=10s. Need more testing.
Here is an example of it:

Fortio 1.3.1-pre running at 8 queries per second, 2->2 procs, for 10s: https://verf.io
00:26:23 I httprunner.go:82> Starting http test for https://verf.io with 4 threads at 8.0 qps
00:26:23 W http_client.go:136> https requested, switching to standard go client
Starting at 8 qps with 4 thread(s) [gomax 2] for 10s : 20 calls each (total 80)
00:26:34 I periodic.go:533> T001 ended after 10.037677773s : 20 calls. qps=1.9924927311172813
00:26:34 I periodic.go:533> T000 ended after 10.039539787s : 20 calls. qps=1.992123187349444
00:26:34 I periodic.go:533> T003 ended after 10.045506626s : 20 calls. qps=1.9909399042389324
00:26:34 I periodic.go:533> T002 ended after 10.051528329s : 20 calls. qps=1.989747165343735
{
"RunType": "HTTP",
"Labels": "verf.io , loadtest-testrun-verfio-20-load-test-job-nxwsd",
Ended after 10.051612431s : 80 calls. qps=7.9589
Sleep times : count 76 avg 0.47779897 +/- 0.01011 min 0.452731099 max 0.49055283 sum 36.3127216
Aggregated Function Time : count 80 avg 0.047964919 +/- 0.009981 min 0.035542295 max 0.073469094 sum 3.8371935
# range, mid point, percentile, count
>= 0.0355423 <= 0.04 , 0.0377711 , 25.00, 20
> 0.04 <= 0.045 , 0.0425 , 31.25, 5
> 0.045 <= 0.05 , 0.0475 , 75.00, 35
> 0.05 <= 0.06 , 0.055 , 86.25, 9
> 0.06 <= 0.07 , 0.065 , 95.00, 7
> 0.07 <= 0.0734691 , 0.0717345 , 100.00, 4
# target 50% 0.0471429
# target 75% 0.05
# target 90% 0.0642857
# target 99% 0.0727753
# target 99.9% 0.0733997
Sockets used: 0 (for perfect keepalive, would be 4)
Code 200 : 80 (100.0 %)
Response Header Sizes : count 80 avg 0 +/- 0 min 0 max 0 sum 0
Response Body/Total Sizes : count 80 avg 127564 +/- 0 min 127564 max 127564 sum 10205120
All done 80 calls (plus 4 warmup) 47.965 ms avg, 8.0 qps
Successfully wrote 2216 bytes of Json data to stdout
"StartTime": "2018-12-29T00:26:24.554751354Z",
"RequestedQPS": "8",
"RequestedDuration": "10s",
"ActualQPS": 7.958922068391078,
"ActualDuration": 10051612431,
"NumThreads": 4,
"Version": "1.3.1-pre",
"DurationHistogram": {

[TenSt]

Not sure if this is still reproducible...

[vtymtsiv]

Hi @TenSt,
Just want to confirm that issue is reproducible.

All done 40 calls (plus 4 warmup) 12.010 ms avg, 8.0 qps
{
  "RunType": "HTTP",
  "Labels": "our secret label name",
  "StartTime": "2021-06-01T09:12:40.576422943Z",
  "RequestedQPS": "8",
  "RequestedDuration": "5s",
Successfully wrote 2766 bytes of Json data to stdout
  "ActualQPS": 7.989349663210383,
  "ActualDuration": 5006665334,
  "NumThreads": 4,

And this kind of results are stored to ConfigMap. And since JSON in broken because of Successfully wrote... line, the UI could not display the result.