Bug 991678

$ man cat
...
       -n, --number
              number all output lines
...

Line numbers are not stable in journalctl output. At any time
- old journal file can be removed, removing entries from the start of the sequence
- a journal file can be added, with entries interleaved anywhere in the sequence.
So in general, using entry numbers to identify events in between different accesses to the journal will not work.

One can identify entries with their "cursors", which can be shown with with -o verbose or -o export, for individual entries, or for the last entry with --show-cursor. Adding cursors to every line in short output is problematic because of their length.

I understand why this might be useful. We could add a short-cursor mode, which would print the cursor at the begginning of each line. Would that work for you?

BTW. you can type -N<enter> in less to get line numbers.

Use-cases are static files attached to bug reports and error analysis in which analysts need to refer to specific line numbers to explain a complex sequence of events.

Bug 988741, Comment 3 provides an example. In Bug 988741, Comment 4, I wanted to refer to two records that contained "Failed to set default route.", but had no way of doing so. Instead, I copied the relevant records into my comment. (They happen to have timestamps, but, IIUC, those are not from journalctl.)

The proposed semantics are simple:

$ journalctl -u NetworkManager -N > j1.log
$ journalctl -u NetworkManager | cat -n > j2.log

For the use-cases above, the line numbers do not need to be identical between runs.

The journalctl man page has one line on cursors that does not explain anything. Is there better documentation somewhere else?

$ man journalctl | less -N
...
    104        -c, --cursor=
    105            Start showing entries from the location in the journal specified by the passed cursor.
...

$ rpm -q systemd
systemd-204-9.fc19.x86_64

Thanks for the tip for enabling line numbering while running less. I didn't know about that.

BTW, I am just starting to use journalctl, and, so far, it is fantastic!

The documentation is going to need some work, if inexperienced users are going to be able to use journalctl cursors. I can experiment and probably figure it out, but here are my first three attempts. I was thinking the cursor would be configurable, in this case with a Bugzilla bug number. 

$ journalctl -u NetworkManager _CURSOR=bz12345
-- Logs begin at Tue 2013-07-30 11:10:14 PDT, end at Sat 2013-08-03 21:15:25 PDT. --
$ journalctl -u NetworkManager -c _CURSOR=bz12345
Failed to seek to cursor: Invalid argument
$ journalctl -u NetworkManager -c bz12345
Failed to seek to cursor: Invalid argument

Several of the -o options appear to be intended for machine processing. They are completely unusable for human interaction, such as in the use-cases described in Comment 3. How are the machine-readable formats intended to be viewed?

$ journalctl -u NetworkManager -o verbose

Option (-o)         Readability
short               human
short-monotonic     human
verbose             machine
export              machine
json                machine
json-pretty         machine
json-sse            machine
cat                 human

$ man journalctl | less -N
...
     65        -o, --output=
     66            Controls the formatting of the journal entries that are shown. Takes one of short, short-monotonic, verbose, export, json, json-pretty, json-sse, cat.  short is the default and generates an
...

I misunderstand what the term "cursor" means. Ordinarily, a user positions a cursor (or a pointer) to mark a location or position. In journalctl terminology, a cursor is essentially a unique record identifier. If the following is an example, journalctl cursors are completely unusable for use-cases requiring human interaction:

$ journalctl -c 's=cad9ce682de9428386cabf61bf27c4a9;i=3aadb;b=b13e01dbde1344bf9e5bc3472fe7ff0f;m=20b06d62f;t=4e2be8560cb51;x=ba5a8fab6bdf7d1e'

Here is an example in which I used line numbers to analyze an strace log:
Bug 974383, Comment 35.

NB: The line numbers were generated with "egrep -n".

Bug 866730, Comment 16: A line number is used to reference a line of Python code.

Attachment 635315 [details]: This unit-test report shows that the locale in record 62 is invalid. (Attached at Bug 866730, Comment 28)

The journalctl output attached to Bug 991393 has the same timestamp repeated 84 times, so the timestamp cannot be used to refer to specific records in the attachment. Line numbers would be completely satfisfactory in this case. The timestamps are still useful, because they show that the events occured very close together.

$ grep '^Aug 02 12:40:43' journalctl-output-bz991393.log | wc -l
84

Bug 991393 - Can't delete connections

Can journalctl support microsecond timestamps?

The strace command has a number of useful options for timestamps:
$ man strace | less -N
...
    120        -t          Prefix each line of the trace with the time of day.
    121 
    122        -tt         If given twice, the time printed will include the microseconds.
    123 
    124        -ttt        If given thrice, the time printed will include the microseconds and the leading portion will be printed as the number of seconds since the epoch.
    125 
    126        -T          Show the time spent in system calls. This records the time difference between the beginning and the end of each system call.
...

This is outside the scope of this bug, but I will put it here for now.

strace has three timestamp options:

$ strace -t sleep 1 2>&1 | head -1
23:56:22 execve("/usr/bin/sleep", ["sleep", "1"], [/* 46 vars */]) = 0

$ strace -tt sleep 1 2>&1 | head -1
23:56:26.180028 execve("/usr/bin/sleep", ["sleep", "1"], [/* 46 vars */]) = 0

$ strace -ttt sleep 1 2>&1 | head -1
1375599389.592077 execve("/usr/bin/sleep", ["sleep", "1"], [/* 46 vars */]) = 0

In the human-readable formats, journalctl has two timestamp options:
MM DD HH:MM:SS and a vaguely[1] specified "monotonic" timestamp (per man page, anyway):

$ journalctl -u NetworkManager -o short | head -2
-- Logs begin at Tue 2013-07-30 11:10:14 PDT, end at Sun 2013-08-04 00:01:02 PDT. --
Jul 30 13:38:03 walnut NetworkManager[506]: <warn> /sys/devices/virtual/net/vnet0: couldn't determine device driver; ignoring...

$ journalctl -u NetworkManager -o short-monotonic | head -2
-- Logs begin at Tue 2013-07-30 11:10:14 PDT, end at Sun 2013-08-04 00:01:02 PDT. --
[17642.432204] walnut NetworkManager[506]: <warn> /sys/devices/virtual/net/vnet0: couldn't determine device driver; ignoring...

[1] Specifically, to what are the whole numbers referenced?

Here is a summary of repeated timestamps in a journalctl log attached to Bug 967521 (Attachment 758633 [details]).

$ cat journalctl-output-bz967521.log | cut -d ' ' -f1,3 | uniq -c | sort -nr | head
    828 Jun 00:25:19
    124 Jun 00:25:58
     53 Jun 00:25:29
     50 Jun 00:25:26
     48 Jun 00:25:21
     43 Jun 00:26:04
     40 Jun 00:25:30
     38 Jun 00:25:31
     34 Jun 00:26:02
     28 Jun 00:25:57

What you say is all true. But adding line numbers is a fairly specific use case. And when adding them, you'll either use a pipe or redirection anyway, in which case 'cat -n' can be inserted there, or use less, in which case less itself can supply the numbers. All in all, I'm not sure if we need another switch in journalctl.

OTOH, I think we should add a microsecond precision output. Attached patch adds journalctl -o short-precise mode. Comments welcome.

Other issues with the documentation of output modes, cursors, etc.: all I can say is "patches welcome!". I guess that the developers have gone over the documentation so many times that they cannot see when something is explained in a way which requires too much prerequisite knowledge.

Created attachment 782489 [details]
add short-precise mode

verbose-precise mode should be added too, I guess.

Thanks. Displaying timestamps with microsecond precision would definitely help with the examples I have given, but the approach of adding yet another format that a user has to remember (or look up) and type does not.

I would suggest adding a -tt option (see strace, Comment 10) and viewing it as a timestamp *modifier*. The modifier alters the timestamp format of the short output from journalctl (no -o option or "-o short").

+    r = strftime(buf, sizeof(buf), "%b %d %H:%M:%S", localtime_r(&t, &tm));
                                                      ^^^^^^^^^
For example, I would like to display timestamps in UTC, instead of local time.
Are you going to add yet more output formats for that?

$ journalctl -o short-utc
$ journalctl -o short-precise-utc

Instead, a timestamp modifier, --utc, would modify the short format timestamp to display the time in UTC.

Usage: journalctl [-tt] [--utc] ...

-tt:    display short output with timestamps having microsecond precision
--utc:  display short output with timestamps in UTC instead of local time
        (see "date --utc". -u is already used by journalctl.)

The monolithic output format approach currently implemented is fine for well-defined, machine-readable formats, but it lacks flexibility for human-readable formatting.

I agree now that line numbers can always be added later. Since microsecond precision timestamps cannot be added later, I am changing the bug summary accordingly:

RFE: journalctl options to display timestamps with microsecond precision and in UTC

(If you would prefer a new RFE bug, instead, I can open one.)

(In reply to Zbigniew Jędrzejewski-Szmek from comment #13)
> Created attachment 782489 [details]
> add short-precise mode
> 
> verbose-precise mode should be added too, I guess.

With a "-tt" option that modifies the timestamp format, no new output format would be needed:

$ journalctl -tt -o verbose

-- Logs begin at Tue 2013-07-30 11:10:14 PDT, end at Sun 2013-08-04 10:01:01 PDT. --
                        vvvvvv
Tue 2013-07-30 11:10:14.123456 PDT [s=078e12fa476c40c3b85873d61882393f;i=3aad9;b=b13e01dbde1344bf9e5bc3472fe7ff0f;m=20ae81086;t=4e2be854205a8;x=e26e64b8b62cf90]
        _TRANSPORT=syslog
...

Likewise for a --utc option:

$ journalctl -tt --utc -o verbose

-- Logs begin at Tue 2013-07-30 11:10:14 PDT, end at Sun 2013-08-04 10:01:01 PDT. --
                        vvvvvv vvv
Tue 2013-07-30 11:10:14.123456 UTC [s=078e12fa476c40c3b85873d61882393f;i=3aad9;b=b13e01dbde1344bf9e5bc3472fe7ff0f;m=20ae81086;t=4e2be854205a8;x=e26e64b8b62cf90]
        _TRANSPORT=syslog
...

With the timestamp modifier approach, the short-monotonic format could be eliminated.

Instead of:
$ journalctl -o short-monotonic

Use:
$ journalctl -tb -o short

-tb: display short output with timestamps in seconds since the previous boot

BTW, monotonic means never decreasing (or never increasing).[1] The timestamps in the short-monotonic format output are anything but monotonic. The timestamps increase until the next boot, immediately after which, the timestamp decreases for one systemd-journal record (411) and then decreases to zero (412). 

$ journalctl -o short-monotonic | less -N
...
    408 [26048.631713] walnut lvm[14378]: 2 logical volume(s) in volume group "vg_neptune" unmonitored
    409 [26048.656330] walnut systemd-journal[283]: Journal stopped
    410 ESC[1;39m-- Reboot --ESC[0m
    411 [   10.313572] walnut systemd-journal[108]: Allowing runtime journal files to grow to 588.3M.
    412 [    0.000000] walnut kernel: Initializing cgroup subsys cpuset
...

[1] monotonic
http://planetmath.org/node/32141
http://www.merriam-webster.com/dictionary/monotonic

(In reply to Zbigniew Jędrzejewski-Szmek from comment #13)
> Created attachment 782489 [details]
> add short-precise mode
> 
> verbose-precise mode should be added too, I guess.

Since verbose mode is, by definition, verbose, it could be made even more verbose by *always* displaying timestamps with microsecond precision. Microsecond precision would be the default in verbose mode.

Or does verbose mode need to conform to some external standard?

$ journalctl -o verbose
-- Logs begin at Tue 2013-07-30 11:10:14 PDT, end at Sun 2013-08-04 20:18:52 PDT. --
                        vvvvvv
Tue 2013-07-30 11:10:14.123456 PDT [s=078e12fa476c40c3b85873d61882393f;i=3aad9;b=b13e01dbde1344bf9e5bc3472fe7ff0f;m=20ae81086;t=4e2be854205a8;x=e26e64b8b62cf90]
	_TRANSPORT=syslog
...

Another useful timestamp format is the number of seconds since the Unix epoch with microsecond precision, for example, 1373698330.456232.

These timestamps can be easily subtracted to calculate the time interval between two events. This example from Bug 974383, Comment 36 was used to explain a previously measured installer shutdown hang time of 90 seconds:

1373698330.456232 - 1373698241.346185 = 89.110047 seconds

See the strace "-ttt" option:

$ man strace | less -N
...
    124        -ttt        If given thrice, the time printed will include the microseconds and the leading portion will be printed as the number of seconds since the epoch.
...

(In reply to Steve Tyler from comment #17)
> Likewise for a --utc option:
> 
> $ journalctl -tt --utc -o verbose
Try TZ=UTC journalctl...

(In reply to Steve Tyler from comment #20)
> Another useful timestamp format is the number of seconds since the Unix
> epoch with microsecond precision, for example, 1373698330.456232.
...
> See the strace "-ttt" option:
Current policy is to treat add new "modes" and treat their names as dash-separated parts. So adding verbose-unix and short-unix is entirely possible (with unix meaning something like -ttt). Short options are scarce, so we don't want to add those until we are sure that a given format is fairly widely used. I like the idea of -t, -tt, and -ttt, but let's get the -o modes working first.

I've modified the patch to add us precision timestamps to verbose output, and will post it to the mailing list for comments.

BTW. It's not necessary to remember all mode names, tab-completions works on them.

Created attachment 783635 [details]
add short-precise mode and make verbose us timestamps too

(In reply to Zbigniew Jędrzejewski-Szmek from comment #22)
...
> BTW. It's not necessary to remember all mode names, tab-completions works on
> them.

Thanks for the tip.

Tab-completion works here:
$ journalctl -o [tab]
cat              json             short-monotonic  
export           short            verbose          

Tab-completion does not work here:
$ TZ=UTC journalctl -o [tab]  # you get a list of files, not a list of options

Or here:
$ TZ=[tab]  # you get a list of files, not a list of time zones

@@ -356,7 +367,7 @@ static int output_verbose(
...
+                format_timestamp_us(ts, sizeof(ts), realtime),
                                  ^^
Thanks.

I would like to test your patch, but get "Protocol not supported" when running journalctl from the build directory. Happens with -204 and -206, happens as root. I am in group wheel.

$ ./journalctl -D /var/log/journal/7725dfc225d14958a625ddaaaea5962b/
Error was encountered while opening journal files: Protocol not supported
$ basename `pwd`
systemd-204

Host is F19, updated:
$ rpm -q systemd
systemd-204-9.fc19.x86_64

Source is from:
http://www.freedesktop.org/software/systemd/systemd-204.tar.xz
http://www.freedesktop.org/software/systemd/systemd-206.tar.xz

Built with:
$ ./configure
$ make journalctl

(In reply to Steve Tyler from comment #24)
> (In reply to Zbigniew Jędrzejewski-Szmek from comment #22)
> ...
> > BTW. It's not necessary to remember all mode names, tab-completions works on
> > them.
> 
> Thanks for the tip.
> 
> Tab-completion works here:
> $ journalctl -o [tab]
> cat              json             short-monotonic  
> export           short            verbose          
> 
> Tab-completion does not work here:
> $ TZ=UTC journalctl -o [tab]  # you get a list of files, not a list of
> options
> 
> Or here:
> $ TZ=[tab]  # you get a list of files, not a list of time zones
Works in zsh, but not in bash. This is a bug in bash-completion. Please file a bug!

(In reply to Steve Tyler from comment #26)
> $ ./journalctl -D /var/log/journal/7725dfc225d14958a625ddaaaea5962b/
> Error was encountered while opening journal files: Protocol not supported
Probably XZ decompression is missing from your journalctl. Can you check that if XZ is enabled in the configure phase?

I was using the defaults. Also tried without success:
$ ./configure --enable-acl

$ grep HAVE_XZ config.log
| #define HAVE_XZ 1
| #define HAVE_XZ 1
HAVE_XZ_FALSE='#'
HAVE_XZ_TRUE=''
#define HAVE_XZ 1

$ basename `pwd`
systemd-204

Rebuilding from the Fedora src package works:
$ ~/src/rpmbuild/BUILDROOT/systemd-204-9.fc19.x86_64//usr/bin/journalctl | head -1
-- Logs begin at Tue 2013-07-30 11:10:14 PDT, end at Wed 2013-08-07 07:01:01 PDT. --

Rebuilt from:
systemd-204-9.fc19.src.rpm

$ diff -u config.h ~/src/rpmbuild/BUILD/systemd-204/config.h
--- config.h	2013-08-07 06:46:31.691737987 -0700
+++ ~/src/rpmbuild/BUILD/systemd-204/config.h	2013-08-07 06:54:45.017533230 -0700
@@ -5,7 +5,7 @@
 /* #undef ARCH_MIPS */
 
 /* Canonical host string. */
-#define CANONICAL_HOST "x86_64-unknown-linux-gnu"
+#define CANONICAL_HOST "x86_64-redhat-linux-gnu"
 
 /* Define if EFI support is to be enabled */
 #define ENABLE_EFI 1
@@ -259,7 +259,7 @@
 #define PACKAGE_VERSION "204"
 
 /* Path of /etc/rc.local script */
-#define RC_LOCAL_SCRIPT_PATH_START "/etc/rc.local"
+#define RC_LOCAL_SCRIPT_PATH_START "/etc/rc.d/rc.local"
 
 /* Path of /usr/sbin/halt.local script */
 #define RC_LOCAL_SCRIPT_PATH_STOP "/usr/sbin/halt.local"

This produces a working configuration:
$ make

This is what I had been building:
$ make journalctl

Is building journalctl alone supposed to work?

(In reply to Steve Tyler from comment #32)
> Is building journalctl alone supposed to work?
It would be nice, but isn't really tested. Might be some strange automake issue.

OK, that was a case of unjustified over-optimization ... :-)

$ ./journalctl --version
systemd 204
+PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ
...
$ ./journalctl --version
systemd 206
+PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ

These timestamps are for the same record, but the timestamps differ in the microseconds:
short-precise:  15:01:01.614369
verbose:        15:01:01.658748

systemd-206 built with attached 0001-logs-show-add-short-precise-mode-with-us-timestamps.patch:

$ TZ=UTC ./journalctl -n 1 -o short-precise -c 's=cad9ce682de9428386cabf61bf27c4a9;i=4505a;b=d82f101d442c47b1a61121aebd2f58ec;m=22213ead6;t=4e35ccf52f27c;x=44079f6ba4c0c483'
-- Logs begin at Tue 2013-07-30 18:10:14 UTC, end at Wed 2013-08-07 15:29:08 UTC. --
Aug 07 15:01:01.614369 walnut run-parts(/etc/cron.hourly)[19250]: finished mcelog.cron

$ TZ=UTC ./journalctl -n 1 -o verbose -c 's=cad9ce682de9428386cabf61bf27c4a9;i=4505a;b=d82f101d442c47b1a61121aebd2f58ec;m=22213ead6;t=4e35ccf52f27c;x=44079f6ba4c0c483'
-- Logs begin at Tue 2013-07-30 18:10:14 UTC, end at Wed 2013-08-07 15:29:08 UTC. --
Wed 2013-08-07 15:01:01.658748 UTC [s=cad9ce682de9428386cabf61bf27c4a9;i=4505a;b=d82f101d442c47b1a61121aebd2f58ec;m=22213ead6;t=4e35ccf52f27c;x=44079f6ba4c0c483]
    _TRANSPORT=syslog
    _UID=0
    _GID=0
    _MACHINE_ID=7725dfc225d14958a625ddaaaea5962b
    _HOSTNAME=walnut
    PRIORITY=5
    SYSLOG_FACILITY=9
    SYSLOG_IDENTIFIER=run-parts(/etc/cron.hourly)
    _SELINUX_CONTEXT=system_u:system_r:system_cronjob_t:s0-s0:c0.c1023
    MESSAGE=finished mcelog.cron
    _BOOT_ID=d82f101d442c47b1a61121aebd2f58ec
    SYSLOG_PID=19250
    _PID=19250
    _SOURCE_REALTIME_TIMESTAMP=1375887661614369

$ man man/journalctl.1 | less -N
...
     80            short-precise
     81                is very similar, but shows timestamps with full microsecond precision.
...

(In reply to Steve Tyler from comment #35)
...
> short-precise:  15:01:01.614369
> verbose:        15:01:01.658748
...
>     _SOURCE_REALTIME_TIMESTAMP=1375887661614369
                                           ^^^^^^

The verbose timestamp appears to be incorrect ...

The second and third timestamps agree in the microseconds:

short-precise       verbose
08:01:01.614369     08:01:01.658748
08:29:08.579713     08:29:08.579713
08:29:08.618644     08:29:08.618644

$ ./journalctl -n 3 -o short-precise -c 's=cad9ce682de9428386cabf61bf27c4a9;i=4505a;b=d82f101d442c47b1a61121aebd2f58ec;m=22213ead6;t=4e35ccf52f27c;x=44079f6ba4c0c483'
-- Logs begin at Tue 2013-07-30 11:10:14 PDT, end at Wed 2013-08-07 09:01:01 PDT. --
Aug 07 08:01:01.614369 walnut run-parts(/etc/cron.hourly)[19250]: finished mcelog.cron
Aug 07 08:29:08.579713 walnut gnome-session[1101]: (gnome-settings-daemon:1172): housekeeping-plugin-WARNING **: Failed to enumerate children of /tmp/systemd-private-MZLTAC: Permission denied
Aug 07 08:29:08.618644 walnut gnome-session[1101]: (gnome-settings-daemon:1172): housekeeping-plugin-WARNING **: Failed to enumerate children of /tmp/systemd-private-391FeQ: Permission denied

$ ./journalctl -n 3 -o verbose -c 's=cad9ce682de9428386cabf61bf27c4a9;i=4505a;b=d82f101d442c47b1a61121aebd2f58ec;m=22213ead6;t=4e35ccf52f27c;x=44079f6ba4c0c483' | grep '^Wed'
Wed 2013-08-07 08:01:01.658748 PDT [s=cad9ce682de9428386cabf61bf27c4a9;i=4505a;b=d82f101d442c47b1a61121aebd2f58ec;m=22213ead6;t=4e35ccf52f27c;x=44079f6ba4c0c483]
Wed 2013-08-07 08:29:08.579713 PDT [s=078e12fa476c40c3b85873d61882393f;i=4505b;b=d82f101d442c47b1a61121aebd2f58ec;m=286a049db;t=4e35d33df5181;x=109d8b7155cc6fa1]
Wed 2013-08-07 08:29:08.618644 PDT [s=078e12fa476c40c3b85873d61882393f;i=4505c;b=d82f101d442c47b1a61121aebd2f58ec;m=286a0e1ee;t=4e35d33dfe994;x=77682b2c610eedb4]

(In reply to Zbigniew Jędrzejewski-Szmek from comment #27)
> (In reply to Steve Tyler from comment #24)
...
> > Tab-completion does not work here:
> > $ TZ=UTC journalctl -o [tab]  # you get a list of files, not a list of
> > options
> > 
> > Or here:
> > $ TZ=[tab]  # you get a list of files, not a list of time zones
> Works in zsh, but not in bash. This is a bug in bash-completion. Please file
> a bug!

Thanks!

Bug 994646 - attempting tab-completion with "TZ=" returns files and directories, not time zones
Bug 994659 - presetting environment variable inhibits tab-completion of command

(In reply to Steve Tyler from comment #36)
> (In reply to Steve Tyler from comment #35)
> ...
> > short-precise:  15:01:01.614369
> > verbose:        15:01:01.658748
> ...
> >     _SOURCE_REALTIME_TIMESTAMP=1375887661614369
>                                            ^^^^^^
> 
> The verbose timestamp appears to be incorrect ...
Most probably the journald timestamp is shown instead of the source timestamp. Thanks for catching that! I'm not sure if there's some reasoning behind this discrepancy or if it is just an error.

This bug is busy enough with the timestamp-precision RFE, that I have opened a separate bug for the UTC RFE. Changing bug summary accordingly.

Bug 994680 - RFE: journalctl option to display timestamps in UTC

Created attachment 784200 [details]
modify verbose mode to prefer source timestamp

(In reply to Zbigniew Jędrzejewski-Szmek from comment #41)
> Created attachment 784200 [details]
> modify verbose mode to prefer source timestamp

Is patch 0002- meant to be applied after 0001-?
If so, should 0001- really be obsoleted?
(It has the man page changes, etc ...)

0001-logs-show-add-short-precise-mode-with-us-timestamps.patch
0002-logs-show-show-source-timestamp-in-verbose-mode.patch

After, or before... they are independent.

OK, thanks. Then 0001- should not be marked as an obsolete attachment:
https://bugzilla.redhat.com/attachment.cgi?id=783635&action=edit

(In reply to Zbigniew Jędrzejewski-Szmek from comment #41)
> Created attachment 784200 [details]
> modify verbose mode to prefer source timestamp

Verifying that the short-precise and verbose timestamps are identical with this patch. Thanks.

$ TZ=UTC ./journalctl -n 3 -o short-precise -c 's=cad9ce682de9428386cabf61bf27c4a9;i=4505a;b=d82f101d442c47b1a61121aebd2f58ec;m=22213ead6;t=4e35ccf52f27c;x=44079f6ba4c0c483'
-- Logs begin at Tue 2013-07-30 18:10:14 UTC, end at Thu 2013-08-08 13:01:01 UTC. --
Aug 07 15:01:01.614369 walnut run-parts(/etc/cron.hourly)[19250]: finished mcelog.cron
Aug 07 15:29:08.579713 walnut gnome-session[1101]: (gnome-settings-daemon:1172): housekeeping-plugin-WARNING **: Failed to enumerate children of /tmp/systemd-private-MZLTAC: Permission denied
Aug 07 15:29:08.618644 walnut gnome-session[1101]: (gnome-settings-daemon:1172): housekeeping-plugin-WARNING **: Failed to enumerate children of /tmp/systemd-private-391FeQ: Permission denied

$ TZ=UTC ./journalctl -n 3 -o verbose -c 's=cad9ce682de9428386cabf61bf27c4a9;i=4505a;b=d82f101d442c47b1a61121aebd2f58ec;m=22213ead6;t=4e35ccf52f27c;x=44079f6ba4c0c483' | grep '^Wed'
Wed 2013-08-07 15:01:01.614369 UTC [s=cad9ce682de9428386cabf61bf27c4a9;i=4505a;b=d82f101d442c47b1a61121aebd2f58ec;m=22213ead6;t=4e35ccf52f27c;x=44079f6ba4c0c483]
Wed 2013-08-07 15:29:08.579713 UTC [s=078e12fa476c40c3b85873d61882393f;i=4505b;b=d82f101d442c47b1a61121aebd2f58ec;m=286a049db;t=4e35d33df5181;x=109d8b7155cc6fa1]
Wed 2013-08-07 15:29:08.618644 UTC [s=078e12fa476c40c3b85873d61882393f;i=4505c;b=d82f101d442c47b1a61121aebd2f58ec;m=286a0e1ee;t=4e35d33dfe994;x=77682b2c610eedb4]

(In reply to Zbigniew Jędrzejewski-Szmek from comment #41)
> Created attachment 784200 [details]
> modify verbose mode to prefer source timestamp

The patch has several error-handling cases. Can you suggest a way to inject faults into the journal that could be used to test those error-handling cases?

(In reply to Steve Tyler from comment #46)
> (In reply to Zbigniew Jędrzejewski-Szmek from comment #41)
> > Created attachment 784200 [details]
> > modify verbose mode to prefer source timestamp
> 
> The patch has several error-handling cases. Can you suggest a way to inject
> faults into the journal that could be used to test those error-handling
> cases?
Error handling should be fine :) We currently don't have any framework to test journal code, which is quite unfortunate. We need to merge the code to import journal entries first I think.

I pushed this as http://cgit.freedesktop.org/systemd/systemd/commit/?id=cf40f0b
and http://cgit.freedesktop.org/systemd/systemd/commit/?id=f02d836, should be available in the next release.