[QPID-8320] [linearstore] Empty journal files orphaned and accumulate when the broker is restarted

• Type: Bug
• Status: Reviewable
• Priority: Major
• Resolution: Unresolved
• Component/s: C++ Broker
• Assignee: Kim van der Riet
• Reporter: Kim van der Riet
• Created: 07/Jun/19 01:58
• Updated: 07/Jun/19 16:45

Description

If a queue journal is filled until the last file in the journal is full, then the store preemptively adds a new journal file to the queue store. This new file is at first uninitialized, but is initialized when it is first used.

If, at recovery, such an uninitialized file exists in a journal, then on recovery, this file is ignored, and a new uninitialized file is added. Hence two uninitialized files now exist in the journal. If the broker is repeatedly stopped, then started with a journal in this state, a new uninitialized file is added for each restart.

In addition, the journal recovery does not dispose of the unused uninitialized files, so they accumulate and continue to exist through multiple restarts.

Reproducer:

Start with a clean store:

rm -rf ~/.qpidd

Start the broker, then:

$ qpid-config add queue --durable test_queue
$ ls ~/.qpidd/qls/jrnl2/test_queue/
f965476e-eea0-4c02-be50-cbfbce6da71a.jrnl
$ hexdump -C ~/.qpidd/qls/jrnl2/test_queue/f965476e-eea0-4c02-be50-cbfbce6da71a.jrnl 
00000000  51 4c 53 66 02 00 00 00  00 00 00 00 00 00 00 00  |QLSf............|
00000010  00 00 00 00 00 00 00 00  01 00 01 00 00 00 00 00  |................|
00000020  00 08 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000030  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
00201000

 
which is an uninitialized empty journal file. Now add 1024 messages that when encoded consume almost 2048 bytes per message on disk. This should fill the first file exactly, so that the last enqueue record coincides with the physical end of the file at offset 0x201000:

$ qpid-send -a test_queue --durable=yes -m 1024 --content-size=1865
$ ls ~/.qpidd/qls/jrnl2/test_queue/
e404051f-8af7-422d-a088-7e957c4db3af.jrnl
f965476e-eea0-4c02-be50-cbfbce6da71a.jrnl
$ hexdump -C  ~/.qpidd/qls/jrnl2/test_queue/f965476e-eea0-4c02-be50-cbfbce6da71a.jrnl | grep QLS
00000000  51 4c 53 66 02 00 00 00  4f c8 73 20 db c2 df 1d  |QLSf....O.s ....|
00001000  51 4c 53 65 02 00 00 00  4f c8 73 20 db c2 df 1d  |QLSe....O.s ....|
00001800  51 4c 53 65 02 00 00 00  4f c8 73 20 db c2 df 1d  |QLSe....O.s ....|

...

001ff800  51 4c 53 65 02 00 00 00  4f c8 73 20 db c2 df 1d  |QLSe....O.s ....|
00200000  51 4c 53 65 02 00 00 00  4f c8 73 20 db c2 df 1d  |QLSe....O.s ....|
00200800  51 4c 53 65 02 00 00 00  4f c8 73 20 db c2 df 1d  |QLSe....O.s ....|

Check that the newly added file is empty:

hexdump -C  ~/.qpidd/qls/jrnl2/test_queue/e404051f-8af7-422d-a088-7e957c4db3af.jrnl
00000000  51 4c 53 66 02 00 00 00  00 00 00 00 00 00 00 00  |QLSf............|
00000010  00 00 00 00 00 00 00 00  01 00 01 00 00 00 00 00  |................|
00000020  00 08 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000030  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
00201000

It is important to check that the second file is empty other than the file header. If there are any records present, then the file will not be considered empty during recovery, and the conditions for the bug will not be met. Depending on network and threading conditions, the store may add in filler records "QLSx" at one or two points during the writing of the files, so this may push the final record to be written in the second file. If this happens, try again, or adjust the number of records down slightly until this condition is met.

Once this condition has been met, stop the broker, then restart it. There will now be two empty files present, the original, plus a new one added at the broker restart.

Start and stop the broker several times. For each recovery, one new empty file is added to the journal. The old files are still present, but are orphaned, and are never moved, used or put back into the Empty File Pool.