test-journal-stream gets confused by crappy clocks about systemd

[keszybz]

On Thu, Jun 11, 2015 at 06:22:20PM -0700, Filipe Brandenburger wrote:

I wonder if it's just me or if others have been seeing these as well?
I use a 20-core machine to run tests fairly regularly and haven't
noticed any failures in those tests, fwiw.

Zbyszek

[filbranden]

So the problem seems to be when generating the data, since once I get a set of bad journal files, I can reproduce the bug consistently using that same dataset...

I pushed a branch with patched test-journal-* binaries taking the directory as argument one and also another commit with the sample data to my fork:
https://github.com/filbranden/systemd/commits/journal_flaky_tests

The bad journals are in commit 02cfaee.

I can reproduce the two problems consistently on that tree:

$ ./test-journal-stream ./journal-stream-c5fOLo
Root directory ./journal-stream-c5fOLo added.
File ./journal-stream-c5fOLo/two.journal added.
File ./journal-stream-c5fOLo/one.journal added.
File ./journal-stream-c5fOLo/three.journal added.
cursor: s=24a579591d6f4ce78ddf27948f3859d1;i=1;b=2c1f7ac736ca42428c32104953a54b5e;m=31ac90884;t=5184b2e570763;x=a27045f3abfa2ebc
        MAGIC=quux
        NUMBER=0
[...]
cursor: s=02818b121e6449058b05deb1cf90259f;i=7;b=2c1f7ac736ca42428c32104953a54b5e;m=31ac908c5;t=5184b2e5707a5;x=10d5bde3ed9372df
        MAGIC=waldo
        NUMBER=7
cursor: s=8f4a38b39e8141fbbf8e1d76d6950ce1;i=3;b=2c1f7ac736ca42428c32104953a54b5e;m=31ac908c8;t=5184b2e5707a7;x=2e44947e51461d7a
        MAGIC=waldo
        NUMBER=9
WARNING: out of order, i=8 u=9
cursor: s=02818b121e6449058b05deb1cf90259f;i=8;b=2c1f7ac736ca42428c32104953a54b5e;m=31ac908c8;t=5184b2e5707a7;x=89a548d0330ef3e4
        MAGIC=waldo
        NUMBER=8
WARNING: out of order, i=9 u=8
cursor: s=02818b121e6449058b05deb1cf90259f;i=9;b=2c1f7ac736ca42428c32104953a54b5e;m=31ac908c8;t=5184b2e5707a7;x=2e44947e51461d7a
        MAGIC=waldo
        NUMBER=9
WARNING: out of order, i=10 u=9
cursor: s=24a579591d6f4ce78ddf27948f3859d1;i=2;b=2c1f7ac736ca42428c32104953a54b5e;m=31ac908ca;t=5184b2e5707a9;x=990c28d21b93ea63
        MAGIC=quux
        NUMBER=10
[...]
WARNING: out of order, i=199 u=198
cursor: s=02818b121e6449058b05deb1cf90259f;i=b4;b=2c1f7ac736ca42428c32104953a54b5e;m=31ac90caa;t=5184b2e570b8a;x=6b41e12d796d16fb
        MAGIC=waldo
        NUMBER=199
WARNING: out of order, i=200 u=199
Assertion 'i == N_ENTRIES' failed at src/journal/test-journal-stream.c:74, function verify_contents(). Aborting.
Aborted (core dumped)

And:

$ ./test-journal-interleaving ./journal-skip-E5IMon
Root directory ./journal-skip-E5IMon added.
File ./journal-skip-E5IMon/two.journal added.
File ./journal-skip-E5IMon/one.journal added.
NUMBER=1
NUMBER=3
Assertion 'n == x' failed at src/journal/test-journal-interleaving.c:87, function test_check_number(). Aborting.
Aborted (core dumped)

It seems the problem is when generating the files... I'm hoping that by pushing the binary files it might be easier to understand why they got into this state where the streaming/interleaving is not really working as expected and then possibly figuring out why they might have been generated with these problems...

Cheers!
Filipe

[poettering]

OK, the interesting thing is this:

cursor: s=8f4a38b39e8141fbbf8e1d76d6950ce1;i=3;b=2c1f7ac736ca42428c32104953a54b5e;m=31ac908c8;t=5184b2e5707a7;x=2e44947e51461d7a
MAGIC=waldo
NUMBER=9
WARNING: out of order, i=8 u=9
cursor: s=02818b121e6449058b05deb1cf90259f;i=8;b=2c1f7ac736ca42428c32104953a54b5e; m=31ac908c8;t=5184b2e5707a7;x=89a548d0330ef3e4
MAGIC=waldo
NUMBER=8

Here we see that the two entries are swapped. When the journal interleaves journal files it does this by comparing a couple of ordering parameters. These ordering parameters are all encoded in the cursor string actually, which is shown in the output. The "s=" param of it is a uuid that identifies a sequence number generator. usually, when journald starts it picks uuid for its generator and then uses it for all journal files it writes and stores the id in the journal file, If you then have two journal files with the same sequence number generator, then you can just compare the sequence numbers to know which one is earlier and which one isn't. The i= parameter is the sequence number. As we can see though both entries have different sequence number generator ids. That's because we wanted to make the test interesting, and thus didn't use the same generator for the three files we generate.

Next is the "b=" param of the cursor. It identifies the boot id. It is followed by the monotonic timestamp as "m=". If two unit files have the same boot id, then we can compare the monotonic timestamps to order entries. This is a secondary ordering key that is used when the sequence number stuff described above doesn't work. Now, as we see both entries have the same boot id (which is of course expected, they were generated by the same process after all), hence the journal uses it to order the entries. but this is now where the problem starts: the entries have the same monotonic time. when the journal encounters that it will hence fallback to using the calendar time (which you see in the t=) for ordering. But that's also the same. At this point the journal cannot really order the entries sensible anymore, they have the exact same sequence information. It then falls back and uses a hash over the full entry to order things, to make the order stable. The x= field shows that hash.

So, the weird thing is that the two entries got both timestamps set to identical values. the test loop asks for the clock on each iteration, and on your system it returned the very same time twice. That means two things:

• Either your system is very fast, or the clock complete crap. Since it's a virtualized env I figure the latter
• we probably should manually ensure the clock monotonically increases in the test tool to work-around systems like yours.

Can you check if fixing the clock to be strictly monotonic in the test loop fixes the issue for you? Just add 1us to the value if you notice that the clock returned in two subsequent iterations is identical.

[filbranden]

Ok, then it's probably a race condition issue.

Yeah this is a virtualized environment with a lot of vcpus so I imagine this might be causing these issues.

For the record, I also have issues with test-barrier some times though not as frequent as these others. In fact I just had it now:

Assertion 'WIFEXITED(status)' failed at src/test/test-barrier.c:228, function test_barrier_wait_next_twice_sync(). Aborting.
FAIL test-barrier (exit status: 134)

I'll try to play with kernel command lines to see if I can get more stable results here. It's fairly easy for me to reproduce this problem, since test-journal-stream reproduces it about 40% to 50% of the time for me.

Not sure what you meant, did you want me to try a specific patch to see if it solves it (without messing with the kernel clocks)? You mean something along the lines of storing the last value in a static variable say in journal_file_append_entry_internal() and incrementing if it's the same to see if that fixes the test? I'll try that to see if it helps...

[poettering]

See patch #271, it makes sure the clock increases strictly monotonically. Does that fix things for you? If so, I'll merge the PR.

Please file a seperate bug for the barrier issue. Thanks.

[filbranden]

Ok so issue with test-journal-stream is fixed by #271, I am now trying a similar fix of saving previous_ts and incrementing ts if it matches on test-journal-interleaving.

Though I wonder if this could cause real problems elsewhere, considering the same timestamp can be returned in two calls in a row... Not sure the code makes different assumptions elsewhere... Though looks like it was only an assumption of this test to make it more "interesting" and in real life it's fine if entries have the same timestamp, since the order will be well defined and if they came from the same sources then everything else should keep the proper ordering (am I correct?)

Yeah I'll file a separate issue for test-barrier, sorry to mix it in here, while it might also be related to clocks it's quite possible that it's not.

(General note: it might be helpful if tests would dump more useful information when they broke, something like Assertion 'WIFEXITED(status)' failed doesn't really help much if we can't really see what's in status or even what's the pid of the process complaining about it, etc. Maybe there are some testing frameworks that could help make failed assertions more useful for debugging?)

Cheers,
Filipe

[poettering]

OK, posted PR #277 that should fix t-j-i.c for you. Please verify.

[poettering]

But yeah, the test was articial, in real life borked clocks should not fuck up things for us that badly. I mean, the way to read this is that two events happened at the very same time, and hence the order in which they ended up on disk was not defined, but the test case assumed it was defined.

[dvdhrm]

Fixed by #277 (and friends).