log file output too verbose

[Peter Baumann]

Log output is containing internal debug output sometimes. In operational installations, this may flood the log file and create excessive file sizes.

Example (bold face is considered excessive):
[2014-03-18 12:57:25] request from 127.0.0.1
Request: 'insert into hdfTest values inv_hdf(#MDD0#, "sampletype=ushort")'…parsing…checking semantics…
QtConversion::checkType() for conversion inv_hdf assume the result marray <char>
evaluating…Error: in conversion factory during create: unsupported format: CVS
Error: QtConversion::evaluate(): conversion failed
Error: cannot parse query (1).
Error number: 381 Token: inv_hdf Line: 1 Column: 28
[2014-03-18 12:57:25] request completed in 1230 usecs.

[Veranika Liaukevich]

About last two bold lines in the example:
At least it makes sense to log only the first message in the place where the exception was thrown, as it is likely to be most informative (not just "conversion failed").

[Veranika Liaukevich]

I found few situations, when an operation fails without logging the reason, but it throws an error with an appropriate error code, so that a client could see the reason of the failure. Is it okay or such failures should be also logged?
(Examples: "access denied, no permission", "Number of cells specified does not match the number of cells of the given spatial domain.")

Additionally, the major part of log files is messages about creating connections, transaction opening/closing, getting next tiles and MDDs. Maybe it would be better to reduce number of such messages as well?

[Dimitar Misev]

I agree that all errors/warnings should be traceable in the logs as well.

Not sure about the second question, personally I have not found those messages about connection/transaction/etc. too useful.

[Veranika Liaukevich]

We can log connections/transactions/etc only in case of their failure in normal installations, and report their correct behaviour in debug installations (via RMDB* macroses).

[Peter Baumann]

what we trace actually is a second discussion. I was simply on syntactical level: the log contains output generated by trace macros. Probably someone has built another "private" logging facility that is statically enabled and disabled, rathern than using one of rmdebug.hh or debug.hh.

If anything needs to be converted from a -DDEBUG enabled trace to regular error/warning then this needs to conform with the standard type of output: one line, no function or "ENTER" prefix, etc.

In any case, output should be short and kept to an absolute minimum to avoid log flooding. Consider millions of requests coming in!

[Dimitar Misev]

The benchmark measurements seem to be completely gone now from the log, can we return at least the query request time? It's useful to have this in the log, especially as it adds a timestamp as well. E.g.

[2014-03-18 12:57:25] request completed in 1230 usecs.

[Veranika Liaukevich]

This information is still available with "—enable-debug".

Right now this "request completed in usecs" message is reported in a function, which doesn't have information about what type of request it processes, so such messages appear for all "open DB", "open TA", "getNextTile" requests together with actual queries times. Of course, it could be changed if we want to see timing reports for only part of requests (which part?).

[Peter Baumann]

indeed, this is at a place where we have few control over selective output.
What about redesigning this into the forthcoming new c/s protocol in a place which is more suitable?

[Veranika Liaukevich]

What is the c/s protocol?

[Peter Baumann]

sorry for the slang; c/s = client-server; currently, we use RNP, and we will replace it by something more modern.

[Dimitar Misev]

I think one timer for how much it takes to evaluate the query (somewhere in servercommm I believe), should be enough. The rest can be enabled only in debug mode, that is fine.

[Peter Baumann]

hm, didn't we have 2 switches, for debug and timing (—enable-benchmark)? Mixing both (i) generates tons of output, hard to analyze and (ii) slows down performance due to the large log activity.
So suggesting to output all timers with —enable-benchmark.

[Dimitar Misev]

These lines should not be in the default non-debug output, they appear on insert:

QtInsert::evaluate() - allocated oid:71169 counter:139
QtInsert::evaluate() - returning oid:71169

[Dimitar Misev]

I tested both modes and it all looks good, so closing the ticket.