server timestamps in logs received from server

[korowa]

Checklist:

• Add tests that demonstrate the correct behavior of the change. Tests should fail without the change.
• Add or update relevant docs, in the docs folder and in code.
• Ensure PR doesn't contain untouched code reformatting: spaces, etc.
• Run flake8 and fix issues.
• Run pytest no tests failed. See https://clickhouse-driver.readthedocs.io/en/latest/development.html.

Context:

For certain types of queries (e.g. backup/restore operations) ClickHouse server might trigger sending logs to the client with significant delay. In such cases, if client has send_logs_level setting enabled, it might be helpful (or less confusing) to also have server event timestamp on client side.

This PR adds server timestamp to log messages by default, and also adds an ability to disable log attributes concatenation to a single string message (which may be helpful in case of structured logging, to avoid parsing the string back to original attributes).

[coveralls]

coverage: 96.26% (+0.009%) from 96.251%
when pulling 2a17ea5 on korowa:server-log-timestamp
into 59ea586 on mymarilyn:master.

[korowa]

@xzkostyan could you please take a look when you have time?

[xzkostyan]

Replacing client datetime with server datetime breaks user experience.

Example: I'm digging into some application issue and grep-ing logs by date/datetime. If server has significant time drift from client there will be no logs in grep output in application logs.

I'd suggest to add another timestamp into log for server timestamp. Result format will be:

        logger.info(
            '[ %s ] [ %s ] [ %s ] {%s} <%s> %s: %s',
            row['server_timestamp'],
            row['host_name'],
            thread_id,
            row['query_id'],
            priority,
            row['source'],
            row['text']
            row['text']
        )

Result log will be

2018-12-14 10:24:53,875 INFO     clickhouse_driver.log: [2018-12-14 10:22:53,875] [ klebedev-ThinkPad-T460 ] [ 25 ] {b328ad33-60e8-4012-b4cc-97f44a7b28f2} <Debug> MemoryTracker: Peak memory usage (for query): 40.23 KiB.

What do you think?

[azat]

@korowa I guess it is not a draft anymore?

[azat]

Maybe this will be better?

Suggested change

	extra = {"server"+k: v for k, v in row.items()}
	extra = {"clickhouse"+k: v for k, v in row.items()}

Also I don't see how does _ added here, can you clarify?

[korowa]

It wasn't -- all test failres has been caused by this.

Regarding attribute prefix -- "server" simply is shorter and doesn't conflict with any of LogRecord attributes, so it seemed to be sufficient, but I don't have any string preferences here.

[korowa]

@xzkostyan I've added server timestamp to the log message as a default behaviour.

In addition, now there is an ability to disable this concatenation, and set log format, using any of ClickHouse log row attributes, which are passed as extra to the log call.

[azat]

BTW defaults can be error prone, and in this particular case it could be avoided, the function is not very common. So, I would rather remove the default here