Enable structured logging in parallel with normal one

[LefterisJP]

Hey guys,

This is a request from the system testing team. Currently the log options are:

   --logformat "std"                    "std" or "raw"

It is going to be really beneficial for our work if one of 2 things happened.

• Either "raw" option means that standard logging is also included in addition to structured logging.
• Or add a "both" option

This will be of extreme help to us since logs are all we have to analyze what may have gone wrong when a test fails due to unexpected values from the structured logging.

[tgerring]

Just to clarify, --logformat dictates the additional information printed along with the log data itself. For example, "std" might print 2015/03/20 17:38:26 [CHAIN] processed block #1 (9401a508...) where raw would print [CHAIN] processed block #1 (9401a508...).

[LefterisJP]

From what I saw when I ran the go client locally "raw" only printed the json structured logging and nothing else. Or maybe I misunderstand what you are saying?

[tgerring]

Yes, this was hacked in because without it, you'd get a mix of structured (JSON) and non-structured (plain text) output.

The structured logging was added as a completely separate logging system and this can be seen in example at

go-ethereum/eth/backend.go

Lines 29 to 30 in 4f5b362

	servlogger = logger.NewLogger("SERV")
	jsonlogger = logger.NewJsonLogger()

. They are different types with different methods.

[zelig]

which means we could have both running and logging into different files. I also think that could be useful.

[LefterisJP]

The elastic search log aggregator (used in system testing) can handle mixed log output perfectly well. It reads and aggregates all JSON log output nicely so that we get our values for the tests and it also aggregates all other non-json data under the non-json category.

This is quite beneficial for debugging. For example I spent quite a bit of time running the client today and for some reason it was not showing any chain head hash log messages. I assumed the DAG was building. But when there was nothing for over 20 mins, I switched back to the normal log output and to my horror I saw it had no coinbase and I needed an account.

So having a mixed log output would be absolutely okay.

[zelig]

Independent flags for json would be better no?:

ethereum -loglevel 5 -logfile /tmp/eth.log -jsonlog -jsonlogfile /tmp/ethlog.json

If you leave out both files, you will likely get garbled mixed output on stdout.

[tgerring]

I've added a new log format "json" which limits the output to JSON messages only (as raw did before). Instead, raw will print all logs matching the requested log level or higher.

--logformat "json" --loglevel "1000" <-- JSON only
--logformat "raw" --loglevel "1000" <-- All logs (JSON + plaintext DebugDetail and higher), intermixed without extra timestamp info
--logformat "raw" --loglevel "5" <-- DebugDetail and above (no JSON) without extra timestamp info
--logformat "std" --loglevel "5" <-- DebugDetail and above (no JSON) with extra timestamp info

[zelig]

can we have something a tad more transparent, my head hurts i still dont get this semantics.
if json is an independent logger lets give it an independent flag and an independent output, much more transparent

[tgerring]

Generally, I agree, but the tradeoff is description/implementation vs time. I'm under the impression that time is more important to system-testing needs than an ideal answer.

FWIW, part of the problem stems from the fact that the logging system depends on different log levels, whereas the structured logging as no inherent log levels (none are defined in the spec, so when should the P2P.Disconnected event be printed? Info? Debug?) So what ends up happening is that we mock JSON as level 1000 and create some special case to allow it to print separate from the rest of the logs.

Ideally, we'd have a way to print our standard logs as plaintext OR json-formatted comments, but we're back to the discussion of how to model the different log systems/messages.

[LefterisJP]

Thanks for doing something so fast Taylor.

Ofcourse I see the problem with having it as it is. We can keep it like this for now if this outputs both log formats as would be beneficial for system testing and make an issue in Github to go with a cleaner solution in the future as suggested by Viktor.

[tgerring]

@LefterisJP New JSON flag has been merged into develop. See #546 (comment) for usage

[LefterisJP]

Thanks. Will now adjust the test scripts.