Bug#863710: journald's most recent entries

[defanor]

Package: systemd
Version: 215-17+deb8u6
Severity: normal

Dear Maintainer,

I have tried to retrieve recent journal entries (with matching fields),
but the retrieved entries were not the most recent ones:

$ journalctl OBJECT_ID=50483 -n 15 | tail -n 1 | cut -c 1-15
May 29 23:05:13
$ journalctl OBJECT_ID=50483 -n 14 | tail -n 1 | cut -c 1-15
May 29 23:05:13
$ journalctl OBJECT_ID=50483 -n 13 | tail -n 1 | cut -c 1-15
May 30 03:04:57
$ journalctl OBJECT_ID=50483 -n 12 | tail -n 1 | cut -c 1-15
May 30 07:05:03
$ journalctl OBJECT_ID=50483 -n 11 | tail -n 1 | cut -c 1-15
May 30 07:05:03
$ journalctl OBJECT_ID=50483 -n 12 | tail -n 1 | cut -c 1-15
May 30 07:05:03
$ journalctl OBJECT_ID=50483 -n 13 | tail -n 1 | cut -c 1-15
May 30 03:04:57
$ journalctl OBJECT_ID=50483 -n 14 | tail -n 1 | cut -c 1-15
May 29 23:05:13
$ journalctl OBJECT_ID=50483 -n 15 | tail -n 1 | cut -c 1-15
May 29 23:05:13

Here is another example, a bit redacted (any <message N> is identical to
another <message N>: the same few messages get inserted there roughly
every 4 hours):

$ journalctl OBJECT_ID=50482 -n 1
-- Logs begin at Sat 2017-05-27 15:00:01 MSK, end at Tue 2017-05-30 11:09:13 MSK. --
May 30 07:03:49 mars mmdb[131728]: <message 1>
$ journalctl OBJECT_ID=50482 -n 2
-- Logs begin at Sat 2017-05-27 15:00:01 MSK, end at Tue 2017-05-30 11:09:14 MSK. --
May 30 03:04:11 mars mmdb[131728]: <message 1>
May 30 03:04:11 mars mmsocks[946]: <message 2>
$ journalctl OBJECT_ID=50482 -n 3
-- Logs begin at Sat 2017-05-27 15:00:01 MSK, end at Tue 2017-05-30 11:09:22 MSK. --
May 29 23:04:18 mars mmdb[131728]: <message 1>
May 29 23:04:19 mars mmsocks[946]: <message 2>
May 29 23:05:19 mars rtms4[35053]: <message 3>
$ journalctl OBJECT_ID=50482 -n 4
-- Logs begin at Sat 2017-05-27 15:00:01 MSK, end at Tue 2017-05-30 11:09:26 MSK. --
May 29 19:06:03 mars mmdb[131728]: <message 1>
May 29 19:06:03 mars mmsocks[946]: <message 2>
May 29 19:07:03 mars rtms4[27816]: <message 3>
May 29 19:07:03 mars mmsocks[946]: <message 4>

Repeating the same commands led to same results, as in the first
example. After that, new messages were inserted, and it got shifted:

$ journalctl OBJECT_ID=50482 -n 1
-- Logs begin at Sat 2017-05-27 15:00:01 MSK, end at Tue 2017-05-30 11:20:31 MSK. --
May 30 11:10:06 mars mmdb[131728]: <message 1>
$ journalctl OBJECT_ID=50482 -n 2
-- Logs begin at Sat 2017-05-27 15:00:01 MSK, end at Tue 2017-05-30 11:21:14 MSK. --
May 30 07:03:49 mars mmdb[131728]: <message 1>
May 30 07:03:51 mars mmsocks[946]: <message 2>

It doesn't seem to happen with OBJECT_ID's where the messages are not as
repetitive. And it works fine if the `-n` option is not specified, or if
its argument is greater than the amount of messages for a given
OBJECT_ID.

Looks like a similar behaviour can be reproduced using systemd units and
shell scripts (just printing the same messages), with no custom fields
or programs, but I wasn't able to get a clean example (got a few
attempts mixed together the only time when it worked that way, and then
it got fixed on its own -- unlike the above examples).

The default /etc/systemd/journald.conf was used.


-- Package-specific info:

-- System Information:
Debian Release: 8.7
  APT prefers stable-updates
  APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)

Kernel: Linux 3.16.0-4-amd64 (SMP w/32 CPU cores)
Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages systemd depends on:
ii  acl             2.2.52-2
ii  adduser         3.113+nmu3
ii  initscripts     2.88dsf-59
ii  libacl1         2.2.52-2
ii  libaudit1       1:2.4-1+b1
ii  libblkid1       2.25.2-6
ii  libc6           2.19-18+deb8u7
ii  libcap2         1:2.24-8
ii  libcap2-bin     1:2.24-8
ii  libcryptsetup4  2:1.6.6-5
ii  libgcrypt20     1.6.3-2+deb8u2
ii  libkmod2        18-3
ii  liblzma5        5.1.1alpha+20120614-2+b3
ii  libpam0g        1.1.8-3.1+deb8u2
ii  libselinux1     2.3-2
ii  libsystemd0     215-17+deb8u6
ii  mount           2.25.2-6
ii  sysv-rc         2.88dsf-59
ii  udev            215-17+deb8u6
ii  util-linux      2.25.2-6

Versions of packages systemd recommends:
ii  dbus            1.8.22-0+deb8u1
pn  libpam-systemd  <none>

Versions of packages systemd suggests:
pn  systemd-ui  <none>

-- no debconf information