|
1 | 1 | import json |
2 | 2 | import logging |
| 3 | +import time |
| 4 | +from logging import LogRecord |
3 | 5 |
|
4 | 6 | from zcs.core.exception import ZcsException |
| 7 | +from zcs.core.session import request_context, RequestState |
5 | 8 |
|
6 | 9 | old_factory = logging.getLogRecordFactory() |
7 | 10 |
|
@@ -31,6 +34,9 @@ def record_factory(*args, **kwargs): |
31 | 34 | class CloudJsonFormatter(logging.Formatter): |
32 | 35 | def format(self, record): |
33 | 36 |
|
| 37 | + # FIXME |
| 38 | + # log op_code, request_id and time deltas |
| 39 | + |
34 | 40 | message = record.getMessage() |
35 | 41 | if record.exc_info and record.original_exception: |
36 | 42 | message = str(record.original_exception) |
@@ -79,8 +85,19 @@ def __init__(self, verbose=False): |
79 | 85 | logging.CRITICAL: logging.Formatter(set_bold_red + base_format + reset) |
80 | 86 | } |
81 | 87 |
|
82 | | - def format(self, record): |
| 88 | + def format(self, record: LogRecord) -> str: |
83 | 89 | formatter = self.FORMATTERS.get(record.levelno) |
| 90 | + |
| 91 | + # Retrieve request state from request context |
| 92 | + request_state: RequestState = request_context.get() |
| 93 | + if request_state: |
| 94 | + time_ns = time.perf_counter_ns() |
| 95 | + delta_ns = time_ns - request_state.getCheckpointNs() |
| 96 | + total_ns = time_ns - request_state.getRequestStartNs() |
| 97 | + request_state.setCheckpointNs(time_ns) |
| 98 | + record.msg = "[OP_CODE:{}][REQ_ID:{}] {} ({:.2f}s delta - {:.2f}s total)".format( |
| 99 | + request_state.getOpCode(), request_state.getRequestId(), record.msg, delta_ns / 1e9, total_ns / 1e9) |
| 100 | + |
84 | 101 | return formatter.format(record) |
85 | 102 |
|
86 | 103 |
|
|
0 commit comments