Skip to content
Snippets Groups Projects
Commit 6bcc6411 authored by Simon McVittie's avatar Simon McVittie
Browse files

Merge branch 'wip/task537' into 'main'

logger: Add timestamps in the log file

See merge request !759
parents 56752344 e245f148
No related branches found
No related tags found
1 merge request!759logger: Add timestamps in the log file
...@@ -31,6 +31,7 @@ static goffset opt_max_bytes = 8 * MEBIBYTE; ...@@ -31,6 +31,7 @@ static goffset opt_max_bytes = 8 * MEBIBYTE;
static gboolean opt_mkfifo = FALSE; static gboolean opt_mkfifo = FALSE;
static gboolean opt_sh_syntax = FALSE; static gboolean opt_sh_syntax = FALSE;
static int opt_terminal_fd = -1; static int opt_terminal_fd = -1;
static gboolean opt_timestamps = TRUE;
static gboolean opt_use_journal = FALSE; static gboolean opt_use_journal = FALSE;
static gboolean opt_parse_level_prefix = FALSE; static gboolean opt_parse_level_prefix = FALSE;
static int opt_file_level = SRT_SYSLOG_LEVEL_DEFAULT_FILE; static int opt_file_level = SRT_SYSLOG_LEVEL_DEFAULT_FILE;
...@@ -169,6 +170,12 @@ static const GOptionEntry option_entries[] = ...@@ -169,6 +170,12 @@ static const GOptionEntry option_entries[] =
G_OPTION_FLAG_NONE, G_OPTION_ARG_INT, &opt_terminal_fd, G_OPTION_FLAG_NONE, G_OPTION_ARG_INT, &opt_terminal_fd,
"An open file descriptor pointing to the terminal", "An open file descriptor pointing to the terminal",
"FD" }, "FD" },
{ "timestamps", '\0',
G_OPTION_FLAG_NONE, G_OPTION_ARG_NONE, &opt_timestamps,
"Prepend a timestamp to each line logged.", NULL },
{ "no-timestamps", '\0',
G_OPTION_FLAG_REVERSE, G_OPTION_ARG_NONE, &opt_timestamps,
"Don't prepend a timestamp to each line logged.", NULL },
{ "use-journal", '\0', { "use-journal", '\0',
G_OPTION_FLAG_NONE, G_OPTION_ARG_NONE, &opt_use_journal, G_OPTION_FLAG_NONE, G_OPTION_ARG_NONE, &opt_use_journal,
"Also log to the systemd Journal.", NULL }, "Also log to the systemd Journal.", NULL },
...@@ -257,6 +264,8 @@ run (int argc, ...@@ -257,6 +264,8 @@ run (int argc,
option_context = g_option_context_new ("[COMMAND [ARGUMENTS...]]"); option_context = g_option_context_new ("[COMMAND [ARGUMENTS...]]");
g_option_context_add_main_entries (option_context, option_entries, NULL); g_option_context_add_main_entries (option_context, option_entries, NULL);
opt_timestamps = _srt_boolean_environment ("SRT_LOGGER_TIMESTAMPS", opt_timestamps);
if (_srt_boolean_environment ("SRT_LOGGER_USE_JOURNAL", FALSE)) if (_srt_boolean_environment ("SRT_LOGGER_USE_JOURNAL", FALSE))
opt_use_journal = TRUE; opt_use_journal = TRUE;
...@@ -321,7 +330,8 @@ run (int argc, ...@@ -321,7 +330,8 @@ run (int argc,
opt_sh_syntax, opt_sh_syntax,
opt_auto_terminal, opt_auto_terminal,
opt_terminal_fd, opt_terminal_fd,
opt_terminal_level); opt_terminal_level,
opt_timestamps);
if (opt_background || !consume_stdin) if (opt_background || !consume_stdin)
{ {
......
...@@ -198,6 +198,11 @@ a **#!/bin/sh** script. ...@@ -198,6 +198,11 @@ a **#!/bin/sh** script.
: Receive an inherited file descriptor for the terminal instead of : Receive an inherited file descriptor for the terminal instead of
opening the terminal device again. opening the terminal device again.
**--timestamps**, **--no-timestamps**
: Do or don't prepend timestamps to each line in the log file.
The default is to add timestamps, unless environment variable
**SRT_LOGGER_TIMESTAMPS=0** is set.
**--use-journal** **--use-journal**
: Write messages to the systemd Journal if possible, even if no : Write messages to the systemd Journal if possible, even if no
**--journal-fd** was given. **--journal-fd** was given.
...@@ -332,6 +337,10 @@ a **#!/bin/sh** script. ...@@ -332,6 +337,10 @@ a **#!/bin/sh** script.
: If set, **logger-0.bash** will use this instead of locating an : If set, **logger-0.bash** will use this instead of locating an
adjacent **srt-logger** executable automatically. adjacent **srt-logger** executable automatically.
`SRT_LOGGER_TIMESTAMPS` (`0` or `1`)
: Set the behaviour if neither **--timestamps** nor **--no-timestamps**
is specified.
`STEAM_CLIENT_LOG_FOLDER` `STEAM_CLIENT_LOG_FOLDER`
: A path relative to `~/.steam/steam` to be used as a default log : A path relative to `~/.steam/steam` to be used as a default log
directory if `$SRT_LOG_DIR` is unset. directory if `$SRT_LOG_DIR` is unset.
......
...@@ -61,7 +61,8 @@ SrtLogger *_srt_logger_new_take (gchar *argv0, ...@@ -61,7 +61,8 @@ SrtLogger *_srt_logger_new_take (gchar *argv0,
gboolean sh_syntax, gboolean sh_syntax,
gboolean terminal, gboolean terminal,
int terminal_fd, int terminal_fd,
int terminal_level); int terminal_level,
gboolean timestamps);
gboolean _srt_logger_run_subprocess (SrtLogger *self, gboolean _srt_logger_run_subprocess (SrtLogger *self,
const char *logger, const char *logger,
......
...@@ -100,6 +100,7 @@ struct _SrtLogger { ...@@ -100,6 +100,7 @@ struct _SrtLogger {
int terminal_level; int terminal_level;
unsigned background : 1; unsigned background : 1;
unsigned sh_syntax : 1; unsigned sh_syntax : 1;
unsigned timestamps : 1;
unsigned use_file : 1; unsigned use_file : 1;
unsigned use_journal : 1; unsigned use_journal : 1;
unsigned use_stderr : 1; unsigned use_stderr : 1;
...@@ -118,6 +119,9 @@ G_DEFINE_TYPE (SrtLogger, _srt_logger, G_TYPE_OBJECT) ...@@ -118,6 +119,9 @@ G_DEFINE_TYPE (SrtLogger, _srt_logger, G_TYPE_OBJECT)
static void static void
_srt_logger_init (SrtLogger *self) _srt_logger_init (SrtLogger *self)
{ {
/* localtime_r() is documented to require this as initialization */
tzset ();
self->child_ready_to_parent = -1; self->child_ready_to_parent = -1;
self->pipe_from_parent = -1; self->pipe_from_parent = -1;
self->original_stderr = -1; self->original_stderr = -1;
...@@ -129,6 +133,7 @@ _srt_logger_init (SrtLogger *self) ...@@ -129,6 +133,7 @@ _srt_logger_init (SrtLogger *self)
self->file_level = SRT_SYSLOG_LEVEL_DEFAULT_FILE; self->file_level = SRT_SYSLOG_LEVEL_DEFAULT_FILE;
self->journal_level = SRT_SYSLOG_LEVEL_DEFAULT_JOURNAL; self->journal_level = SRT_SYSLOG_LEVEL_DEFAULT_JOURNAL;
self->terminal_level = SRT_SYSLOG_LEVEL_DEFAULT_TERMINAL; self->terminal_level = SRT_SYSLOG_LEVEL_DEFAULT_TERMINAL;
self->timestamps = TRUE;
} }
/* We need to have the log open read/write, otherwise the kernel won't let /* We need to have the log open read/write, otherwise the kernel won't let
...@@ -197,6 +202,7 @@ _srt_logger_class_init (SrtLoggerClass *cls) ...@@ -197,6 +202,7 @@ _srt_logger_class_init (SrtLoggerClass *cls)
* @sh_syntax: If true, write `SRT_LOGGER_READY=1\n` to stdout when ready * @sh_syntax: If true, write `SRT_LOGGER_READY=1\n` to stdout when ready
* @terminal: If true, try to log to the terminal * @terminal: If true, try to log to the terminal
* @terminal_fd: Existing file descriptor for the terminal, or -1 * @terminal_fd: Existing file descriptor for the terminal, or -1
* @timestamps: If true, prepend a timestamp to each line
* *
* Create a new logger. All parameters are "stolen". * Create a new logger. All parameters are "stolen".
*/ */
...@@ -218,7 +224,8 @@ _srt_logger_new_take (char *argv0, ...@@ -218,7 +224,8 @@ _srt_logger_new_take (char *argv0,
gboolean sh_syntax, gboolean sh_syntax,
gboolean terminal, gboolean terminal,
int terminal_fd, int terminal_fd,
int terminal_level) int terminal_level,
gboolean timestamps)
{ {
SrtLogger *self = g_object_new (SRT_TYPE_LOGGER, NULL); SrtLogger *self = g_object_new (SRT_TYPE_LOGGER, NULL);
...@@ -241,6 +248,7 @@ _srt_logger_new_take (char *argv0, ...@@ -241,6 +248,7 @@ _srt_logger_new_take (char *argv0,
self->use_terminal = !!terminal; self->use_terminal = !!terminal;
self->terminal_fd = terminal_fd; self->terminal_fd = terminal_fd;
self->terminal_level = terminal_level; self->terminal_level = terminal_level;
self->timestamps = !!timestamps;
return g_steal_pointer (&self); return g_steal_pointer (&self);
} }
...@@ -485,10 +493,16 @@ _srt_logger_setup (SrtLogger *self, ...@@ -485,10 +493,16 @@ _srt_logger_setup (SrtLogger *self,
"Unable to stat \"%s\"", "Unable to stat \"%s\"",
self->filename); self->filename);
message = g_string_new (g_get_prgname ()); /* As a special case, the message saying that we opened the log file
* always has a timestamp, even if timestamps are disabled in general */
message = g_string_new ("");
date_time = g_date_time_new_now_local (); date_time = g_date_time_new_now_local ();
/* We record the time zone here, but not in subsequent lines:
* the reader can infer that subsequent lines are in the same
* time zone as this message. */
timestamp = g_date_time_format (date_time, "%F %T%z"); timestamp = g_date_time_format (date_time, "%F %T%z");
g_string_append_printf (message, "[%d]: Log opened %s\n", getpid (), timestamp); g_string_append_printf (message, "[%s] %s[%d]: Log opened\n",
timestamp, g_get_prgname (), getpid ());
glnx_loop_write (self->file_fd, message->str, message->len); glnx_loop_write (self->file_fd, message->str, message->len);
} }
...@@ -788,6 +802,9 @@ _srt_logger_run_subprocess (SrtLogger *self, ...@@ -788,6 +802,9 @@ _srt_logger_run_subprocess (SrtLogger *self,
g_strdup_printf ("--terminal-fd=%d", self->terminal_fd)); g_strdup_printf ("--terminal-fd=%d", self->terminal_fd));
} }
if (!self->timestamps)
g_ptr_array_add (logger_argv, g_strdup ("--no-timestamps"));
if (self->parse_level_prefix) if (self->parse_level_prefix)
g_ptr_array_add (logger_argv, g_strdup ("--parse-level-prefix")); g_ptr_array_add (logger_argv, g_strdup ("--parse-level-prefix"));
...@@ -1195,6 +1212,9 @@ logger_process_partial_line (SrtLogger *self, ...@@ -1195,6 +1212,9 @@ logger_process_partial_line (SrtLogger *self,
/* /*
* @self: The logger * @self: The logger
* @level: Severity level between `LOG_EMERG` and `LOG_DEBUG`
* @line_start_time: If we are writing timestamps, the time at which the
* first byte of the @line was received
* @line: (array length=len): Pointer to the beginning of a log message * @line: (array length=len): Pointer to the beginning of a log message
* @len: Number of bytes to process, including the trailing newline * @len: Number of bytes to process, including the trailing newline
* *
...@@ -1205,6 +1225,7 @@ logger_process_partial_line (SrtLogger *self, ...@@ -1205,6 +1225,7 @@ logger_process_partial_line (SrtLogger *self,
static void static void
logger_process_complete_line (SrtLogger *self, logger_process_complete_line (SrtLogger *self,
int level, int level,
time_t line_start_time,
const char *line, const char *line,
size_t len) size_t len)
{ {
...@@ -1291,6 +1312,23 @@ logger_process_complete_line (SrtLogger *self, ...@@ -1291,6 +1312,23 @@ logger_process_complete_line (SrtLogger *self,
} }
} }
if (line_start_time != 0)
{
/* We use glibc time formatting rather than GDateTime here,
* to reduce malloc/free in the main logging loop. */
char buf[32];
size_t buf_used = 0;
struct tm tm;
/* If we can't format the timestamp for some reason, just don't
* output it */
if (localtime_r (&line_start_time, &tm) == &tm)
{
buf_used = strftime (buf, sizeof (buf), "[%F %T] ", &tm);
glnx_loop_write (self->file_fd, buf, buf_used);
}
}
glnx_loop_write (self->file_fd, line, len); glnx_loop_write (self->file_fd, line, len);
} }
} }
...@@ -1313,6 +1351,7 @@ _srt_logger_process (SrtLogger *self, ...@@ -1313,6 +1351,7 @@ _srt_logger_process (SrtLogger *self,
size_t already_processed_partial_line = 0; size_t already_processed_partial_line = 0;
size_t filled = 0; size_t filled = 0;
ssize_t res; ssize_t res;
time_t line_start_time = 0;
if (!_srt_logger_setup (self, error)) if (!_srt_logger_setup (self, error))
return FALSE; return FALSE;
...@@ -1358,6 +1397,9 @@ _srt_logger_process (SrtLogger *self, ...@@ -1358,6 +1397,9 @@ _srt_logger_process (SrtLogger *self,
if (res < 0) if (res < 0)
return glnx_throw_errno_prefix (error, "Error reading standard input"); return glnx_throw_errno_prefix (error, "Error reading standard input");
if (self->timestamps && filled == 0)
line_start_time = time (NULL);
/* We never touch the last byte of buf while reading */ /* We never touch the last byte of buf while reading */
filled += (size_t) res; filled += (size_t) res;
g_assert (filled < sizeof (buf)); g_assert (filled < sizeof (buf));
...@@ -1432,6 +1474,7 @@ _srt_logger_process (SrtLogger *self, ...@@ -1432,6 +1474,7 @@ _srt_logger_process (SrtLogger *self,
if (parsed_level_prefix_size < len) if (parsed_level_prefix_size < len)
logger_process_complete_line (self, logger_process_complete_line (self,
line_level, line_level,
line_start_time,
buf + parsed_level_prefix_size, buf + parsed_level_prefix_size,
len - parsed_level_prefix_size); len - parsed_level_prefix_size);
......
...@@ -169,7 +169,9 @@ class TestLogger(BaseTest): ...@@ -169,7 +169,9 @@ class TestLogger(BaseTest):
def test_concurrent_logging(self, use_sh_syntax=False) -> None: def test_concurrent_logging(self, use_sh_syntax=False) -> None:
''' '''
If there is more than one writer for the same log file, rotation If there is more than one writer for the same log file, rotation
is disabled to avoid data loss is disabled to avoid data loss.
Also exercise explicitly disabling timestamps via command-line option.
''' '''
with tempfile.TemporaryDirectory() as tmpdir: with tempfile.TemporaryDirectory() as tmpdir:
with open(str(Path(tmpdir, 'cat.txt')), 'w'): with open(str(Path(tmpdir, 'cat.txt')), 'w'):
...@@ -194,6 +196,7 @@ class TestLogger(BaseTest): ...@@ -194,6 +196,7 @@ class TestLogger(BaseTest):
self.logger + [ self.logger + [
'--filename=log.txt', '--filename=log.txt',
'--log-directory', tmpdir, '--log-directory', tmpdir,
'--no-timestamps',
'--rotate=50', '--rotate=50',
] + args, ] + args,
stdin=subprocess.PIPE, stdin=subprocess.PIPE,
...@@ -253,9 +256,10 @@ class TestLogger(BaseTest): ...@@ -253,9 +256,10 @@ class TestLogger(BaseTest):
lines = [ lines = [
line line
for line in lines for line in lines
if not line.startswith(b'srt-logger[') if b'] srt-logger[' not in line
] ]
# There are no timestamps
self.assertEqual( self.assertEqual(
lines, lines,
[(b'.' * 20) + b'\n'] * 5, [(b'.' * 20) + b'\n'] * 5,
...@@ -270,8 +274,9 @@ class TestLogger(BaseTest): ...@@ -270,8 +274,9 @@ class TestLogger(BaseTest):
def test_default_filename_from_argv0(self) -> None: def test_default_filename_from_argv0(self) -> None:
''' '''
Exercise default filename from COMMAND, and also default Exercise default filename from COMMAND,
log directory from $SRT_LOG_DIR default log directory from $SRT_LOG_DIR,
and timestamps being on by default
''' '''
with tempfile.TemporaryDirectory() as tmpdir: with tempfile.TemporaryDirectory() as tmpdir:
with open(str(Path(tmpdir, 'cat.txt')), 'w'): with open(str(Path(tmpdir, 'cat.txt')), 'w'):
...@@ -280,6 +285,7 @@ class TestLogger(BaseTest): ...@@ -280,6 +285,7 @@ class TestLogger(BaseTest):
proc = subprocess.Popen( proc = subprocess.Popen(
[ [
'env', 'env',
'-u', 'SRT_LOGGER_TIMESTAMPS',
'SRT_LOG_DIR=' + tmpdir, 'SRT_LOG_DIR=' + tmpdir,
] + self.logger + [ ] + self.logger + [
'--no-auto-terminal', '--no-auto-terminal',
...@@ -326,12 +332,17 @@ class TestLogger(BaseTest): ...@@ -326,12 +332,17 @@ class TestLogger(BaseTest):
with open(str(Path(tmpdir, 'cat.txt')), 'rb') as reader: with open(str(Path(tmpdir, 'cat.txt')), 'rb') as reader:
content = reader.read() content = reader.read()
self.assertIn(b'hello, world\n', content) self.assertRegex(
content,
rb'(?m)^\[\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d\] '
rb'hello, world\n',
)
def test_default_filename_from_identifier(self) -> None: def test_default_filename_from_identifier(self) -> None:
''' '''
Exercise default filename from --identifier, and also Exercise default filename from --identifier,
default log directory from Steam default log directory from Steam,
and explicitly enabling timestamps
''' '''
with tempfile.TemporaryDirectory() as tmpdir: with tempfile.TemporaryDirectory() as tmpdir:
Path( Path(
...@@ -347,9 +358,11 @@ class TestLogger(BaseTest): ...@@ -347,9 +358,11 @@ class TestLogger(BaseTest):
'env', 'env',
'HOME=' + tmpdir, 'HOME=' + tmpdir,
'STEAM_CLIENT_LOG_FOLDER=my-logs', 'STEAM_CLIENT_LOG_FOLDER=my-logs',
'SRT_LOGGER_TIMESTAMPS=0',
] + self.logger + [ ] + self.logger + [
'--identifier=foo', '--identifier=foo',
'--no-auto-terminal', '--no-auto-terminal',
'--timestamps',
], ],
stdin=subprocess.PIPE, stdin=subprocess.PIPE,
stdout=STDERR_FILENO, stdout=STDERR_FILENO,
...@@ -375,7 +388,11 @@ class TestLogger(BaseTest): ...@@ -375,7 +388,11 @@ class TestLogger(BaseTest):
'rb' 'rb'
) as reader: ) as reader:
content = reader.read() content = reader.read()
self.assertIn(b'hello, world\n', content) self.assertRegex(
content,
rb'(?m)^\[\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d\] '
rb'hello, world\n',
)
def test_exec_fallback_to_cat(self) -> None: def test_exec_fallback_to_cat(self) -> None:
with tempfile.TemporaryDirectory() as tmpdir: with tempfile.TemporaryDirectory() as tmpdir:
...@@ -583,6 +600,14 @@ class TestLogger(BaseTest): ...@@ -583,6 +600,14 @@ class TestLogger(BaseTest):
self.test_concurrent_logging(use_sh_syntax=True) self.test_concurrent_logging(use_sh_syntax=True)
def test_rotation(self) -> None: def test_rotation(self) -> None:
'''
Exercise log rotation, and explicitly disabling timestamps
via command-line option.
It's convenient to exercise timestamps being disabled in this
test, because if they were enabled, they'd throw off the arithmetic
for the point at which log rotation occurs.
'''
with tempfile.TemporaryDirectory() as tmpdir: with tempfile.TemporaryDirectory() as tmpdir:
proc = subprocess.Popen( proc = subprocess.Popen(
self.logger + [ self.logger + [
...@@ -590,6 +615,7 @@ class TestLogger(BaseTest): ...@@ -590,6 +615,7 @@ class TestLogger(BaseTest):
'--log-directory', tmpdir, '--log-directory', tmpdir,
'--rotate=1K', '--rotate=1K',
'--no-auto-terminal', '--no-auto-terminal',
'--no-timestamps',
], ],
stdin=subprocess.PIPE, stdin=subprocess.PIPE,
stdout=STDERR_FILENO, stdout=STDERR_FILENO,
...@@ -623,16 +649,27 @@ class TestLogger(BaseTest): ...@@ -623,16 +649,27 @@ class TestLogger(BaseTest):
with open(str(Path(tmpdir, 'log.previous.txt')), 'rb') as reader: with open(str(Path(tmpdir, 'log.previous.txt')), 'rb') as reader:
content = reader.read() content = reader.read()
self.assertIn(b'middle message\n', content) # There are no timestamps here, so it's a line on its own
self.assertRegex(content, b'(?m)^middle message\n')
with open(str(Path(tmpdir, 'log.txt')), 'rb') as reader: with open(str(Path(tmpdir, 'log.txt')), 'rb') as reader:
content = reader.read() content = reader.read()
self.assertIn(b'last message\n', content) self.assertIn(b'last message\n', content)
def test_rotation_no_suffix(self) -> None: def test_rotation_no_suffix(self) -> None:
'''
Exercise log rotation, and explicitly disabling timestamps via
environment.
It's convenient to exercise timestamps being disabled in this
test, because if they were enabled, they'd throw off the arithmetic
for the point at which log rotation occurs.
'''
with tempfile.TemporaryDirectory() as tmpdir: with tempfile.TemporaryDirectory() as tmpdir:
proc = subprocess.Popen( proc = subprocess.Popen(
self.logger + [ [
'env', 'SRT_LOGGER_TIMESTAMPS=0',
] + self.logger + [
'--filename=log', '--filename=log',
'--log-directory', tmpdir, '--log-directory', tmpdir,
'--rotate=1K', '--rotate=1K',
...@@ -670,7 +707,8 @@ class TestLogger(BaseTest): ...@@ -670,7 +707,8 @@ class TestLogger(BaseTest):
with open(str(Path(tmpdir, 'log.previous')), 'rb') as reader: with open(str(Path(tmpdir, 'log.previous')), 'rb') as reader:
content = reader.read() content = reader.read()
self.assertIn(b'middle message\n', content) # There are no timestamps here, so it's a line on its own
self.assertRegex(content, b'(?m)^middle message\n')
with open(str(Path(tmpdir, 'log')), 'rb') as reader: with open(str(Path(tmpdir, 'log')), 'rb') as reader:
content = reader.read() content = reader.read()
......
0% Loading or .
You are about to add 0 people to the discussion. Proceed with caution.
Please register or to comment