Re: [PATCH v2 0/2] printk_ringbuffer: don't needlessly wrap data blocks around

[Petr Mladek <pmladek@suse.com>]

On Thu 2025-09-11 17:30:36, Petr Mladek wrote:
> On Fri 2025-09-05 17:41:50, Daniil Tatianin wrote:
> > This series fixes the issue where data blocks would wrap in cases where the last
> > data block perfectly fits the ring. This caused whatever was at the beginning of
> > the ring to get discarded in this case, and the data block would get put there
> > even though it could be put at the end of the data ring just fine without
> > discarding anything.
> > 
> > Fixing this issue also allows to simplify the check in data_check_size,
> > previously it would ensure there's space for a trailing id, which we
> > don't need anymore.
> > 
> > v0->v1:
> > - Fix severely broken code alignment
> > 
> > v1->v2:
> > - Rename & invert get_next_lpos -> is_blk_wrapped
> > - Add a new commit for changing the logic in data_check_size
> 
> The patchset looks good to me. But I wanted to do some tests
> and it failed. I did the following:
> 
> 1. Applied this patchset on top of printk/linux.git, branch for-next,
>    https://git.kernel.org/pub/scm/linux/kernel/git/printk/linux.git/log/?h=for-next
> 
>    I this branch because it contains a new KUnit test for the printk
>    ring buffer.

The KUnit test fails even without this patchset, see below.

> 2. I applied the following patch:
> 
>        + It reduces the size of the data ring. If I count it correctly
> 	 it should be 256 (2 << 8).
> 
>        + It increases the maximal size of the text so that the maximal
> 	 record size is 256.
> 
> 3. I built it with Kasan enabled:
> 
> 	$> grep KASAN .config
> 	CONFIG_KASAN_SHADOW_OFFSET=0xdffffc0000000000
> 	CONFIG_HAVE_ARCH_KASAN=y
> 	CONFIG_HAVE_ARCH_KASAN_VMALLOC=y
> 	CONFIG_CC_HAS_KASAN_GENERIC=y
> 	CONFIG_CC_HAS_KASAN_SW_TAGS=y
> 	CONFIG_KASAN=y
> 	CONFIG_CC_HAS_KASAN_MEMINTRINSIC_PREFIX=y
> 	CONFIG_KASAN_GENERIC=y
> 	# CONFIG_KASAN_OUTLINE is not set
> 	CONFIG_KASAN_INLINE=y
> 	CONFIG_KASAN_STACK=y
> 	CONFIG_KASAN_VMALLOC=y
> 	# CONFIG_KASAN_KUNIT_TEST is not set
> 	# CONFIG_KASAN_EXTRA_INFO is not set
> 
> 
> 4. I loaded the test module:
> 
> 	# depmod
> 	# modprobe printk_ringbuffer_kunit_test
> 
> I am not sure if it is caused by this patchset or

Hmm, the KUnit test fails even after reverting this patchset.
I havn't hit the WARN_ON_ONCE() in get_data() yet.
But the data seem to be corrupted.

This is from two runs:

[   45.808363] printk_ringbuffer_kunit_test: module verification failed: signature and/or required key missing - tainting kernel
[   45.820389] KTAP version 1
[   45.820682] 1..1
[   45.822088]     KTAP version 1
[   45.822387]     # Subtest: printk-ringbuffer
[   45.822729]     # module: printk_ringbuffer_kunit_test
[   45.822759]     1..1
[   45.824001]     # test_readerwriter: running for 10000 ms
[   45.825762]     # test_readerwriter: start thread 001 (writer)
[   45.826187]     # test_readerwriter: start thread 002 (writer)
[   45.826607]     # test_readerwriter: start thread 003 (writer)
[   45.826881]     # test_readerwriter: start thread 004 (writer)
[   45.827193]     # test_readerwriter: start thread 005 (writer)
[   45.827512]     # test_readerwriter: start thread 006 (writer)
[   45.827724]     # test_readerwriter: start thread 007 (writer)
[   45.827951]     # test_readerwriter: start thread 008 (writer)
[   45.828200]     # test_readerwriter: start thread 009 (writer)
[   45.828353]     # test_readerwriter: start thread 010 (writer)
[   45.828548]     # test_readerwriter: starting test
[   45.828553]     # test_readerwriter: start thread 011 (writer)
[   45.828575]     # test_readerwriter: start reader
[   45.828662]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=15 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x80O\x81\x88\xff\xff
[   45.835013]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=16 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x01
[   45.837261]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=17 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x01
[   45.837415]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=18 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[   45.841872]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=19 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[   45.844515]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=20 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[   45.844663]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=21 size=1111638594 text=
[   45.844816]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=22 size=1111638594 text=
[   45.849842]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=23 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[   45.849990]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=24 size=1111638594 text=
[   55.841113]     # test_readerwriter: end reader: read=14 seq=28
[   55.841869]     # test_readerwriter: completed test
[   55.846197]     # test_readerwriter: end thread 011: wrote=15338812
[   55.847027]     # test_readerwriter: end thread 010: wrote=13113829
[   55.847838]     # test_readerwriter: end thread 009: wrote=16786746
[   55.848469]     # test_readerwriter: end thread 008: wrote=14555662
[   55.849240]     # test_readerwriter: end thread 007: wrote=13117536
[   55.849873]     # test_readerwriter: end thread 006: wrote=13147885
[   55.850478]     # test_readerwriter: end thread 005: wrote=16799892
[   55.851085]     # test_readerwriter: end thread 004: wrote=14468908
[   55.851692]     # test_readerwriter: end thread 003: wrote=16795798
[   55.852311]     # test_readerwriter: end thread 002: wrote=15430923
[   55.852918]     # test_readerwriter: end thread 001: wrote=13106357
[   55.853645]     # test_readerwriter.speed: slow
[   55.853681]     not ok 1 test_readerwriter
[   55.854080] not ok 1 printk-ringbuffer
[  202.098871]     KTAP version 1
[  202.099389]     # Subtest: printk-ringbuffer
[  202.099901]     # module: printk_ringbuffer_kunit_test
[  202.100039]     1..1
[  202.103458]     # test_readerwriter: running for 10000 ms
[  202.105324]     # test_readerwriter: start thread 001 (writer)
[  202.106870]     # test_readerwriter: start thread 002 (writer)
[  202.107413]     # test_readerwriter: start thread 003 (writer)
[  202.107805]     # test_readerwriter: start thread 004 (writer)
[  202.108256]     # test_readerwriter: start thread 005 (writer)
[  202.108486]     # test_readerwriter: start thread 006 (writer)
[  202.108777]     # test_readerwriter: start thread 007 (writer)
[  202.109017]     # test_readerwriter: start thread 008 (writer)
[  202.109608]     # test_readerwriter: start thread 009 (writer)
[  202.110028]     # test_readerwriter: starting test
[  202.110039]     # test_readerwriter: start thread 011 (writer)
[  202.110054]     # test_readerwriter: start reader
[  202.110138]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=5 size=1111638594 text=
[  202.110279]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=8 size=1111638594 text=
[  202.110407]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=9 size=94 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[  202.110792]     # test_readerwriter: start thread 010 (writer)
[  202.111323]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=10 size=1111638594 text=
[  202.120582]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=12 size=1111638594 text=
[  212.257479]     # test_readerwriter: end reader: read=12 seq=16
[  212.258233]     # test_readerwriter: completed test
[  212.259613]     # test_readerwriter: end thread 011: wrote=13062252
[  212.260418]     # test_readerwriter: end thread 010: wrote=13059061
[  212.261766]     # test_readerwriter: end thread 009: wrote=16683360
[  212.262379]     # test_readerwriter: end thread 008: wrote=16680568
[  212.263016]     # test_readerwriter: end thread 007: wrote=16687096
[  212.263644]     # test_readerwriter: end thread 006: wrote=16646963
[  212.264265]     # test_readerwriter: end thread 005: wrote=16708452
[  212.264878]     # test_readerwriter: end thread 004: wrote=13065967
[  212.265531]     # test_readerwriter: end thread 003: wrote=13090840
[  212.266098]     # test_readerwriter: end thread 002: wrote=13074259
[  212.266695]     # test_readerwriter: end thread 001: wrote=13083747
[  212.267471]     # test_readerwriter.speed: slow
[  212.267502]     not ok 1 test_readerwriter
[  212.268136] not ok 1 printk-ringbuffer


It is interesting that it did read the same size=XXX values for
several seq= numbers. It was 1111638594 in two independent runs.

1st run:

               BAD RECORD: seq=15 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x80O\x81\x88\xff\xff
[   45.835013]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=16 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x01
[   45.837261]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=17 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB\x01
[   45.837415]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=18 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[   45.841872]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=19 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[   45.844515]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=20 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[   45.844663]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=21 size=1111638594 text=
[   45.844816]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=22 size=1111638594 text=
[   45.849842]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=23 size=217 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[   45.849990]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=24 size=1111638594 text=

2nd run: triggered by: echo 1 > /sys/kernel/debug/kunit/printk-ringbuffer/run


               BAD RECORD: seq=5 size=1111638594 text=
[  202.110279]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=8 size=1111638594 text=
[  202.110407]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=9 size=94 text=BBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB
[  202.110792]     # test_readerwriter: start thread 010 (writer)
[  202.111323]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=10 size=1111638594 text=
[  202.120582]     # test_readerwriter: EXPECTATION FAILED at kernel/printk/printk_ringbuffer_kunit_test.c:80
               BAD RECORD: seq=12 size=1111638594 text=


Best Regards,
Petr