JSON output includes non-JSON error messages

[omarkohl]

When executing (with fio version 3.12):

fio --output=file.json --output-format=json config.fio

Where config.fio contains the following:

[global]
create_on_open=1
kb_base=1000

[10MiB_x_1200_8T]
filesize=10MiB
nrfiles=150
numjobs=8
bs=512KiB
rw=write
openfiles=1
group_reporting=1
file_service_type=sequential
thread=4
directory=fio

Sometimes file.json contains something as the following:

fio: pid=4896, err=5/file:ioengines.c:351, func=td_io_queue, error=Input/output error
fio: pid=4128, err=5/file:ioengines.c:351, func=td_io_queue, error=Input/output error
fio: pid=4420, err=5/file:ioengines.c:351, func=td_io_queue, error=Input/output error
fio: pid=4008, err=5/file:ioengines.c:351, func=td_io_queue, error=Input/output error
fio: pid=4588, err=5/file:ioengines.c:351, func=td_io_queue, error=Input/output error
fio: pid=5192, err=5/file:ioengines.c:351, func=td_io_queue, error=Input/output error
fio: pid=4864, err=5/file:ioengines.c:351, func=td_io_queue, error=Input/output error
{
  "fio version" : "fio-3.12",
  "timestamp" : 1547028960,
  "timestamp_ms" : 1547028960664,
  "time" : "Wed Jan 9 10:16:00 2019",
  "global options" : {
    "kb_base" : "1000",
    "create_on_open" : "1"
  },
  "jobs" : [
    {

Those error messages are not JSON so parsing the file causes errors.

[sitsofe]

@omarkohl If you separate stderr from stdout do you still get this issue?

[omarkohl]

How should I separate them? This is something fio does. I'm not piping the output to a file. fio is writing the file. It is possible that fio does not separate stdout and stderr but I didn't see any flag to influence this behaviour.

[sitsofe]

@omarkohl Oh! I'd missed that... I guess when creating a JSON file perhaps fio needs to learn how to make an errors dictionary item. If you can cope with multiple dictionaries being made before the "regular" one would that work?

[omarkohl]

Anything that can be parsed by a standard JSON library would be great :-)

Am 26. März 2019 06:17:31 MEZ schrieb Sitsofe Wheeler [email protected]:

@omarkohl Oh! I'd missed that... I guess when creating a JSON file perhaps fio needs to learn how to make an errors dictionary item. If you can cope with multiple dictionaries being made before the "regular" one would that work?

-- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/axboe/fio/issues/731#issuecomment-476478965

[sitsofe]

@omarkohl Even if they were entirely separate "stanzas"?

[omarkohl]

I'm not exactly sure what that means but for me anything that can be parsed by the default JSON parser of say Java, Python, Go, etc. would be great. If any manual preprocessing is necessary that would not be so great.

Am 26. März 2019 07:17:55 MEZ schrieb Sitsofe Wheeler [email protected]:

@omarkohl Even if they were entirely separate "stanzas"?

-- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/axboe/fio/issues/731#issuecomment-476490443

[bitreaper]

Knowing how FIO outputs JSON, and how we read it, along with how we have to process errors, I think I understand what @sitsofe is asking, @sitsofe please correct me if I'm wrong. Currently the start of output would begin with JSON, and be a contained dictionary itself:

{ "fio version" : "fio-3.12", "timestamp" : 1547028960, "timestamp_ms" : 1547028960664, "time" : "Wed Jan 9 10:16:00 2019", "global options" : { "kb_base" : "1000", "create_on_open" : "1" ( the rest of JSON performance data here) ... }

When errors happen, they end up being printed outside of the JSON data like how it's shown in the example above. When attempting to parse the output with a JSON parser, it pukes with an exception of being fed malformed JSON.

@sitsofe Are you suggesting another top level stanza, which would effectively be considered two JSON documents? Like this:

{ (JSON performance data here) } { (error JSON data here) }

If this is the case, I think I could deal with it. We could nest any output from FIO with a spare set of square brackets, and then feed that to the JSON parser. If the parser returns a list with two items, we know an error occurred and take action accordingly. It would be preferable to what we do right now which is rely on the JSON parser throwing up an exception to know that we have to comb through for possible errors.

As a bonus, if we're getting errors wrapped up in JSON, it would reduce the number of parser regexes we have to write. That's where most of the brittleness I've witnessed through the years in automated systems creeps in. A regex that didn't catch the one small variation that nobody expected. Having the data from an error wrapped up in a data structure would be a nice touch... :)

[sitsofe]

{
(JSON performance data here)
}
{
(error JSON data here)
}

@bitreaper That's exactly what I meant.

[vincentkfu]

If you are using python, here is one work-around for this issue:

https://github.com/axboe/fio/blob/fio-3.17/t/run-fio-tests.py#L281

[davclark]

I have little say in the matter, but I think it should be pretty straightforward to keep stderr as-is and write errors there. Then, you redirect true output to the JSON file. Is it not possible to do this? Could it be done using bashisms? E.g., the initial command could be converted to:

fio --output-format=json config.fio > file.json

And then errors would still go to stderr? This seems to work upon casual inspection...

[joshginter]

As @davclark said, it does seem that we can achieve the desired result by doing bash redirection. This seems to imply that this should be a very simple fix.

[sitsofe]

@joshginter [...] This seems to imply that this should be a very simple fix.

It's not as straightforward as you might think. Forcing the particular error mention by the original commenter ("fio: pid=4896, err=5/file:ioengines.c:351, func=td_io_queue, error=Input/output error") to go to stderr could be done by changing https://github.com/axboe/fio/blob/fio-3.21/backend.c#L1902 to use log_err()). However, the bigger question is "what about all the other uses of log_info()"? While many are outputting error information some are not and arguably want to be seen inline (e.g. https://github.com/axboe/fio/blob/fio-3.21/engines/cpu.c#L92 ) but would still mess up JSON. Not insurmountable but not a quick fix.

@joshginter Would you be willing to submit a patch converting the log_info() uses that are actually outputting error messages as a first stab?

[joshginter]

@sitsofe Ya. It's something I'd like to take a look at this weekend. I haven't spent any significant time looking at the FIO code up to this point so there'll be a decent amount of time for me to get comfortable with what I'm looking at. But your suggestion of starting with error uses of log_info is a good starting point.

I'm want to look into another JSON problem as well. #672 . That case is taking a look at an issue related to the status-interval option and having multiple "statuses" in a single JSON file. When I have personally seen these "non-JSON" errors in files of my own they always appear at the top. But looking at your answer I'm thinking it's probably possible for them to appear "between" status intervals so they'd be in the middle of the file as well, so any long-term solution to these non-JSON messages should work for that status-interval case as well.

As for long term solutions I can think of two ideas:

1. When using a json output format and an output file it seems reasonable that a person would always expect the output to be a properly formatted JSON file first and foremost. In that case output the logging messages to the console, and only put JSON into the file. As someone using FIO json output this is more in line with my expectations. We could provide an option for having a second output file for the non-JSON outputs if allowing the user to count on output redirection is not enough.
2. When in JSON format place log messages into a buffer array rather than printing them in real time every time the status is printed put each message from the buffer into a json object called "message_log" (or similar) and add it to the status. So you'd end up with each status containing a "jobs", "disk-util", and "message-log" object. We'd probably have to set the buffer to some reasonable size limit and if older messages have to get overwritten that's something we can live with?

[simonebaracchi]

I have found an issue which appears to be related (if not the same issue). I also have found a possible workaround.

The issue seems to be with the order of processing command line arguments. By switching the order of the cli arguments, the issue disappears.

Example 1: this triggers the issue fio --output-format=json+ --client=10.50.42.51 /tmp/fio-script

Example 2: this fixes the issue. Just moving --output-format=json+ to the end of the line fixes it. fio --client=10.50.42.51 /tmp/fio-script --output-format=json+