Add microsecond accuracy to log timestamps
This is useful while debugging and trying to check events across other
outputs such as pcap files, process logs, etc.
Change-Id: I43bb5c6e9977189251802bc2b078c52eb046bab8
diff --git a/selftest/process_test.ok.ign b/selftest/process_test.ok.ign
index 0abd7d5..b817f5a 100644
--- a/selftest/process_test.ok.ign
+++ b/selftest/process_test.ok.ign
@@ -1,7 +1,7 @@
PATH='[^']*' PATH=[$PATH]
/tmp/[^/ '"]* [TMP]
pid=[0-9]* pid=[PID]
-....-..-.._..:..:.. [DATETIME]
+....-..-.._..:..:..\....... [DATETIME]
'[^']*/selftest/process_test/foo.py' [$0]
"[^"]*/selftest/process_test/foo.py" [$0]
, line [0-9]* , line [LINE]
diff --git a/src/osmo_gsm_tester/log.py b/src/osmo_gsm_tester/log.py
index c4a6629..a9f16c2 100644
--- a/src/osmo_gsm_tester/log.py
+++ b/src/osmo_gsm_tester/log.py
@@ -23,6 +23,7 @@
import traceback
import contextlib
import atexit
+from datetime import datetime # we need this for strftime as the one from time doesn't carry microsecond info
from inspect import getframeinfo, stack
from .util import is_dict
@@ -80,8 +81,8 @@
target.log(origin, category, level, src, messages, named_items)
-LONG_DATEFMT = '%Y-%m-%d_%H:%M:%S'
-DATEFMT = '%H:%M:%S'
+LONG_DATEFMT = '%Y-%m-%d_%H:%M:%S.%f'
+DATEFMT = '%H:%M:%S.%f'
# may be overridden by regression tests
get_process_id = lambda: '%d-%d' % (os.getpid(), time.time())
@@ -105,7 +106,7 @@
all_levels = None
# redirected by logging test
- get_time_str = lambda self: time.strftime(self.log_time_fmt)
+ get_time_str = lambda self: datetime.now().strftime(self.log_time_fmt)
# sink that gets each complete logging line
log_write_func = None
diff --git a/src/osmo_gsm_tester/process.py b/src/osmo_gsm_tester/process.py
index d24bf3d..4b68ef5 100644
--- a/src/osmo_gsm_tester/process.py
+++ b/src/osmo_gsm_tester/process.py
@@ -21,6 +21,7 @@
import time
import subprocess
import signal
+from datetime import datetime
from . import log, test, event_loop
from .util import Dir
@@ -55,7 +56,7 @@
path = self.run_dir.new_child(name)
f = open(path, 'w')
self.dbg(path)
- f.write('(launched: %s)\n' % time.strftime(log.LONG_DATEFMT))
+ f.write('(launched: %s)\n' % datetime.now().strftime(log.LONG_DATEFMT))
f.flush()
self.outputs[name] = (path, f)
return f