IOExample_pytest_test_rootiomixertoomuch test output not completely deterministic

The test IOExample_pytest_test_rootiomixertoomuch occasionally fails (e.g. https://lhcb-nightlies.web.cern.ch/nightly/lhcb-master-mr/12681/LHCb/x86_64_v2-el9-gcc13-opt/tests#IOExample_pytest_test_rootiomixertoomuch) with diffs like

 RootIOMixer          INFO Took event from file 5
 CountBanks           INFO evt got 836 banks
 RootIOMixer          INFO Took event from file 5
-HLTControlFlowMgr   ERROR End of input reached earlier than expected
 RootIOMixer          INFO Took event from file 2
 RootIOMixer       SUCCESS Reading Event record 1 within rootIOMixerInput_2inf.dst
+HLTControlFlowMgr   ERROR End of input reached earlier than expected

It would appear the problem is the exact order of the output messages are not completely deterministic, so now and then differs from the reference.

It should be made deterministic.

assigned to @sponce

mentioned in merge request !4958 (merged)

@jonrob Did you notice (or maybe @msaur) whether this test used to fail before migration to pytest?

Here a LineSorter is added to stdout preprocessor (apart default preprocessor this feature is used only in 3 tests, all in IOExample, and this test is one of them), so one of possible sources of the issue is LineSorter does not work as expected in pytest preprocessing the standard output.

Yeah, I had a very similar thought. I have not checked yet though when the issues started, if they are related to the pytest migration or not.

I remember such a fluctuations from a few weeks ago, so surely before PyTest migration - just not sure if that was this exact test or another one.

Plus, if that would be due to LineSorter, wouldn't it fail on more than just one platform?

I tend to agree, I think its been going on for a while.

Just looking at what LineSorter actually does

https://gitlab.cern.ch/lhcb/LHCb/-/blob/master/GaudiConf/python/GaudiConf/QMTest/BaseTest.py?ref_type=heads#L1034

I confess I am struggling a little to understand exactly what it is doing...

OK see the comment

# Special preprocessor sorting the list of strings (whitespace separated)
#  that follow a signature on a single line

So it seems it only sorts the output after the specific line. So if that lines jumps around in the whole log its not clear to me if this ever really helped...

LineSorter sorts strings inside 1 line, I am not sure why it is used here. Maybe the intention of the test develoepr was to sort the line in a block of standard output but in reality it is not what LineSorter is doing (or there was a hack or something I am not aware of)

Perhaps the thing to do here is not compare to a full reference, but instead require the test to run OK (0 return code) and just check for the existance of the line

HLTControlFlowMgr   ERROR End of input reached earlier than expected

in the output. Then it would not matter precisely when it appears.

b.t.w. if the test is running single threaded, and I think it is, I also wonder why the order is not deterministic. Perhaps that question should be answered first.

I suggest we wait for @sponce to return and comment here.

OK (if the order will remain indeterministic I think it makes sense to do exactly what you proposed)

I need to see what I can do when I come back, but this change of order is kind of expected, as we never really run in single threaded mode when I/O is concerned : there is one thread doing I/O in the back of the main thread. So pure I/O errors and processing go in parallel and create this discrepancy.

Ok thanks. Perhaps then the thing to do in this case is not compare to a full ref, but just check for the existance of that one line in the output ?

Now that I took the time to look at it, I believe using LineSorter was a mistake and it should just have been SortGroupOfLines with a regexp like "(RootIOMixer|CountBanks|HLTControlFlowMgr) .*".

Implemented in !4975 (merged)

mentioned in merge request !4975 (merged)

closed with merge request !4975 (merged)

mentioned in commit f8e979f9