2018-04-06 09:49:22

by Sebastian Ott

[permalink] [raw]
Subject: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

Hi,

Today's kernel oopsed on s390. Bisect points to:
3c8ba0d61d04 ("kernel.h: Retain constant expression output for max()/min()")

[ 1.898277] dasd-eckd 0.0.3304: DASD with 4 KB/block, 21636720 KB total size, 48 KB/track, compatible disk layout
[ 1.898308] ------------[ cut here ]------------
[ 1.898310] kernel BUG at block/bio.c:1798!
[ 1.898320] illegal operation: 0001 ilc:1 [#1] PREEMPT SMP
[ 1.898322] Modules linked in:
[ 1.898325] CPU: 2 PID: 68 Comm: kworker/2:1 Not tainted 4.16.0-09576-g38c23685b273 #130
[ 1.898326] Hardware name: IBM 3906 M04 704 (LPAR)
[ 1.898332] Workqueue: events do_kick_device
[ 1.898334] Krnl PSW : 0000000008df7044 00000000dbc29dcd (bio_split+0xb2/0xb8)
[ 1.898338] R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:2 PM:0 RI:0 EA:3
[ 1.898340] Krnl GPRS: 000003d100000008 000003d100000000 00000000facfa100 0000000000000000
[ 1.898341] 0000000001400000 00000000fae0b100 00000000fa9c7738 00000000facfa100
[ 1.898342] 00000000facfa188 0000000000000000 0000000000000000 0000000000000000
[ 1.898343] 00000000f7bb0000 000003d100000000 0000000000521530 00000000fa9c75e8
[ 1.898351] Krnl Code: 000000000050e41a: f0c00004ebaf srp 4(13,%r0),2991(%r14),0
000000000050e420: f0a0000407f4 srp 4(11,%r0),2036,0
#000000000050e426: a7f40001 brc 15,50e428
>000000000050e42a: a7f40001 brc 15,50e42c
000000000050e42e: 0707 bcr 0,%r7
000000000050e430: c00400000000 brcl 0,50e430
000000000050e436: eb6ff0480024 stmg %r6,%r15,72(%r15)
000000000050e43c: a7f13f80 tmll %r15,16256
[ 1.898365] Call Trace:
[ 1.898367] ([<0000000001088020>] 0x1088020)
[ 1.898371] [<0000000000528de6>] blk_mq_make_request+0x76/0x768
[ 1.898375] [<000000000051923a>] generic_make_request+0xea/0x2c0
[ 1.898376] [<00000000005194b4>] submit_bio+0xa4/0x1a0
[ 1.898378] [<00000000003ab934>] submit_bh_wbc+0x1c4/0x218
[ 1.898380] [<00000000003ac5d2>] block_read_full_page+0x352/0x3f8
[ 1.898383] [<00000000002ad1ae>] do_read_cache_page+0x19e/0x3c0
[ 1.898385] [<00000000002ad400>] read_cache_page+0x30/0x40
[ 1.898387] [<0000000000533900>] read_dev_sector+0x58/0xe8
[ 1.898389] [<0000000000538252>] read_lba.isra.0+0x12a/0x1b8
[ 1.898391] dasd-eckd 0.0.3307: DASD with 4 KB/block, 21636720 KB total size, 48 KB/track, compatible disk layout
[ 1.898394] [<0000000000538748>] efi_partition+0x198/0x660
[ 1.898396] [<0000000000535c8c>] check_partition+0x15c/0x2b8
[ 1.898398] [<0000000000534092>] rescan_partitions+0xea/0x3f8
[ 1.898400] [<000000000052ee10>] blkdev_reread_part+0x40/0x60
[ 1.898403] [<0000000000674a10>] dasd_scan_partitions+0x90/0x148
[ 1.898405] [<000000000066eaa2>] dasd_change_state+0x912/0xba0
[ 1.898407] [<000000000066ed78>] do_kick_device+0x48/0x98
[ 1.898410] [<00000000001644b2>] process_one_work+0x1d2/0x458
[ 1.898410] ------------[ cut here ]------------
[ 1.898411] kernel BUG at block/bio.c:1798!
[ 1.898420] [<0000000000164794>] worker_thread+0x5c/0x478
[ 1.898422] [<000000000016b700>] kthread+0x148/0x160
[ 1.898425] [<000000000083e54a>] kernel_thread_starter+0x6/0xc
[ 1.898427] [<000000000083e544>] kernel_thread_starter+0x0/0xc
[ 1.898428] Last Breaking-Event-Address:
[ 1.898429] [<000000000050e426>] bio_split+0xae/0xb8
[ 1.898431]
[ 1.898432] illegal operation: 0001 ilc:1 [#2]
[ 1.898432] Kernel panic - not syncing: Fatal exception: panic_on_oops



Bisect log and config attached. I'll look at min/max users in the affected
areas later today.

Sebastian


Attachments:
config (58.14 kB)
bisect.log (2.37 kB)
Download all attachments

2018-04-06 16:50:50

by Kees Cook

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Fri, Apr 6, 2018 at 2:47 AM, Sebastian Ott <[email protected]> wrote:
> Today's kernel oopsed on s390. Bisect points to:
> 3c8ba0d61d04 ("kernel.h: Retain constant expression output for max()/min()")
>
> [ 1.898277] dasd-eckd 0.0.3304: DASD with 4 KB/block, 21636720 KB total size, 48 KB/track, compatible disk layout
> [ 1.898308] ------------[ cut here ]------------
> [ 1.898310] kernel BUG at block/bio.c:1798!

Well that's extremely bad. :(

> Bisect log and config attached. I'll look at min/max users in the affected
> areas later today.

Seems like a comparison of objdump output with/without the patch may
be needed. And why is this s390 only? Ugh.

-Kees

--
Kees Cook
Pixel Security

2018-04-06 18:06:29

by Kees Cook

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Fri, Apr 6, 2018 at 9:47 AM, Kees Cook <[email protected]> wrote:
> On Fri, Apr 6, 2018 at 2:47 AM, Sebastian Ott <[email protected]> wrote:
>> Today's kernel oopsed on s390. Bisect points to:
>> 3c8ba0d61d04 ("kernel.h: Retain constant expression output for max()/min()")
>>
>> [ 1.898277] dasd-eckd 0.0.3304: DASD with 4 KB/block, 21636720 KB total size, 48 KB/track, compatible disk layout
>> [ 1.898308] ------------[ cut here ]------------
>> [ 1.898310] kernel BUG at block/bio.c:1798!
>
> Well that's extremely bad. :(
>
>> Bisect log and config attached. I'll look at min/max users in the affected
>> areas later today.
>
> Seems like a comparison of objdump output with/without the patch may
> be needed. And why is this s390 only? Ugh.

I did a objdump diff with your .config and it's rather large -- mostly
seems to be register swaps, so it's not easy to browse.

BTW, what version of gcc did you use? I built using:

s390x-linux-gnu-gcc (Ubuntu 7.3.0-13ubuntu1) 7.3.0

-Kees

--
Kees Cook
Pixel Security

2018-04-06 18:14:30

by Sebastian Ott

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Fri, 6 Apr 2018, Kees Cook wrote:
> On Fri, Apr 6, 2018 at 9:47 AM, Kees Cook <[email protected]> wrote:
> > On Fri, Apr 6, 2018 at 2:47 AM, Sebastian Ott <[email protected]> wrote:
> >> Today's kernel oopsed on s390. Bisect points to:
> >> 3c8ba0d61d04 ("kernel.h: Retain constant expression output for max()/min()")
> >>
> >> [ 1.898277] dasd-eckd 0.0.3304: DASD with 4 KB/block, 21636720 KB total size, 48 KB/track, compatible disk layout
> >> [ 1.898308] ------------[ cut here ]------------
> >> [ 1.898310] kernel BUG at block/bio.c:1798!
> >
> > Well that's extremely bad. :(
> >
> >> Bisect log and config attached. I'll look at min/max users in the affected
> >> areas later today.
> >
> > Seems like a comparison of objdump output with/without the patch may
> > be needed. And why is this s390 only? Ugh.
>
> I did a objdump diff with your .config and it's rather large -- mostly
> seems to be register swaps, so it's not easy to browse.

Yes, I'm looking at that too.

> BTW, what version of gcc did you use? I built using:

gcc version 7.2.0 (GCC)


2018-04-09 16:22:54

by Sebastian Ott

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Fri, 6 Apr 2018, Kees Cook wrote:
> On Fri, Apr 6, 2018 at 2:47 AM, Sebastian Ott <[email protected]> wrote:
> > Today's kernel oopsed on s390. Bisect points to:
> > 3c8ba0d61d04 ("kernel.h: Retain constant expression output for max()/min()")
> >
> > [ 1.898277] dasd-eckd 0.0.3304: DASD with 4 KB/block, 21636720 KB total size, 48 KB/track, compatible disk layout
> > [ 1.898308] ------------[ cut here ]------------
> > [ 1.898310] kernel BUG at block/bio.c:1798!
>
> Well that's extremely bad. :(

What happened is that the bio build by the partition detection code was
attempted to be split by the block layer because the block queue had a
max_sector setting of 0. blk_queue_max_hw_sectors uses min_not_zero.

Both of the following return 0 on my machine:
+ pr_warn("%u\n", min_not_zero(100, 1000));
+ pr_warn("%u\n", min_not_zero(1000, 100));

So, we now know what failed...the question is why?

Sebastian


2018-04-09 17:05:33

by Sebastian Ott

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Mon, 9 Apr 2018, Sebastian Ott wrote:
> On Fri, 6 Apr 2018, Kees Cook wrote:
> > On Fri, Apr 6, 2018 at 2:47 AM, Sebastian Ott <[email protected]> wrote:
> > > Today's kernel oopsed on s390. Bisect points to:
> > > 3c8ba0d61d04 ("kernel.h: Retain constant expression output for max()/min()")
> > >
> > > [ 1.898277] dasd-eckd 0.0.3304: DASD with 4 KB/block, 21636720 KB total size, 48 KB/track, compatible disk layout
> > > [ 1.898308] ------------[ cut here ]------------
> > > [ 1.898310] kernel BUG at block/bio.c:1798!
> >
> > Well that's extremely bad. :(
>
> What happened is that the bio build by the partition detection code was
> attempted to be split by the block layer because the block queue had a
> max_sector setting of 0. blk_queue_max_hw_sectors uses min_not_zero.
>
> Both of the following return 0 on my machine:
> + pr_warn("%u\n", min_not_zero(100, 1000));
> + pr_warn("%u\n", min_not_zero(1000, 100));
>
> So, we now know what failed...the question is why?

I copied these macros to a userspace program to easily test it on other
machines/compilers. ....maybe I did something wrong but min_not_zero did
not work - even on fedora on an x86 laptop.

Sebastian


Attachments:
test.c (1.16 kB)

2018-04-09 17:08:14

by Linus Torvalds

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Mon, Apr 9, 2018 at 9:18 AM, Sebastian Ott <[email protected]> wrote:
>
> Both of the following return 0 on my machine:
> + pr_warn("%u\n", min_not_zero(100, 1000));
> + pr_warn("%u\n", min_not_zero(1000, 100));

Oooh.

[ Raises hand, and says "I know, I know, pick me, pick me" ]

min_not_zero() hasinternal variables "__x" and "__y".

And "__cmp_once()" has internal variables "__x" and "__y".

When min_not_zero does

min(__x, __y));

that expands to crazy stuff.

Out old "min()" had the internal variables called "min1" and "min2",
which is crazy too.

Linus

2018-04-09 17:15:16

by Sebastian Ott

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Mon, 9 Apr 2018, Linus Torvalds wrote:
> On Mon, Apr 9, 2018 at 9:18 AM, Sebastian Ott <[email protected]> wrote:
> >
> > Both of the following return 0 on my machine:
> > + pr_warn("%u\n", min_not_zero(100, 1000));
> > + pr_warn("%u\n", min_not_zero(1000, 100));
>
> Oooh.
>
> [ Raises hand, and says "I know, I know, pick me, pick me" ]
>
> min_not_zero() hasinternal variables "__x" and "__y".
>
> And "__cmp_once()" has internal variables "__x" and "__y".

Argh....so obvious now :-)

When I change these it works.

Sebastian


2018-04-09 17:19:01

by Linus Torvalds

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Mon, Apr 9, 2018 at 10:03 AM, Linus Torvalds
<[email protected]> wrote:
>
> Our old "min()" had the internal variables called "min1" and "min2",
> which is crazy too.

Actually, no, it used the really cumbersome "__UNIQUE_ID" and then
passed that odd as the name 'min1/2',

Ugh, I find that really nasty to read, but it was obviously done
because we hit this before.

And our __UNIQUE_ID() macro is garbage anyway, since it falls back on
the line number, which doesn't really work for macros anyway. But we
have proper macros for both clang and gcc, so maybe we should ignore
the broken fallback.

A patch like the attached, perhaps?

Linus


Attachments:
patch.diff (1.03 kB)

2018-04-09 17:20:26

by Linus Torvalds

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Mon, Apr 9, 2018 at 10:11 AM, Sebastian Ott <[email protected]> wrote:
>
> Argh....so obvious now :-)
>
> When I change these it works.

Mind testing the slightly more complex patch I just emailed out, and I
can commit it?

Linus

2018-04-09 17:32:04

by Sebastian Ott

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Mon, 9 Apr 2018, Linus Torvalds wrote:
> On Mon, Apr 9, 2018 at 10:03 AM, Linus Torvalds
> <[email protected]> wrote:
> >
> > Our old "min()" had the internal variables called "min1" and "min2",
> > which is crazy too.
>
> Actually, no, it used the really cumbersome "__UNIQUE_ID" and then
> passed that odd as the name 'min1/2',
>
> Ugh, I find that really nasty to read, but it was obviously done
> because we hit this before.
>
> And our __UNIQUE_ID() macro is garbage anyway, since it falls back on
> the line number, which doesn't really work for macros anyway. But we
> have proper macros for both clang and gcc, so maybe we should ignore
> the broken fallback.
>
> A patch like the attached, perhaps?

I applied this on top of 38c23685b273cfb4ccf31a199feccce3bdcb5d83
and everything works as expected.

Thanks!


2018-04-09 17:36:16

by Linus Torvalds

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Mon, Apr 9, 2018 at 10:14 AM, Linus Torvalds
<[email protected]> wrote:
>
> Ugh, I find that really nasty to read, but it was obviously done
> because we hit this before.

Side note, we have a *lof* of those "__x" and "__y" names in the helper macros.

Clearly min/max was the only one we really had ever hit (because it
used to have that UNIQUE_ID thing), and the patch I sent hopefully
fixes the only real problem, but it would be good to perhaps look at
this in general.

And no, -Wshadow still isn't the right answer, because while it warns
about this, it also warns about a lot of perfectly normal cases where
we have shadowing of names but it doesn't really matter.

Maybe "make __UNIQUE_ID easier to use and encourage that model" is the
right answer.

Right now "__UNIQUE_ID" is actually really nasty in several ways:

(1) the already mentioned "the fallback is broken for same-line use"

This doesn't really matter because both gcc and clang have _true_
unique macros, but we should probably remove the fallback as "know
broken and not really guaranteed to give a unique ID"

(2) The argument you give to __UNIQUE_ID() is pointless. The only
reason it exists is because the broken fallback case is so broken and
by definition __LINE__ will be the same not only if two different
macros are used on the same line, but for trivial and common case of
*one* macro using it.

That second problem is a problem only because it encourages crazy
naming. For example, in the patch I sent I used "__UNIQUE_ID(__x)". If
we actually just wanted a prefix, it would be more logical to just use
"__UNIQUE_ID(x)" instead, but then macro arghument expansion means
that you don't really get "x" as the prefix, but whatever the
_arghument_ x was.

So then I have to use "__x" or something just to avoid argument
expansion. Maybe I should just have used a plain number (which cannot
have the argument expansion issue), but that doesn't work because the
prefix is directly attached to the unique number, so using
__UNIQUE_ID(1) and __UNIQUE_ID(2) is actually unsafe _too_, because
the numbers can end up not being unique at all.

I really do dislike __UNIQUE_ID() for all these reasons. It has
various really subtle problems that make it unnecessarily hard to use
and/or have odd nasty issues.

I think there's a reason why __UNIQUE_ID() really isn't used much.

Linus

2018-04-09 18:08:36

by Kees Cook

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Mon, Apr 9, 2018 at 10:14 AM, Linus Torvalds
<[email protected]> wrote:
> On Mon, Apr 9, 2018 at 10:03 AM, Linus Torvalds
> <[email protected]> wrote:
>>
>> Our old "min()" had the internal variables called "min1" and "min2",
>> which is crazy too.
>
> Actually, no, it used the really cumbersome "__UNIQUE_ID" and then
> passed that odd as the name 'min1/2',
>
> Ugh, I find that really nasty to read, but it was obviously done
> because we hit this before.

Ooof. Nice find.

> And our __UNIQUE_ID() macro is garbage anyway, since it falls back on
> the line number, which doesn't really work for macros anyway. But we
> have proper macros for both clang and gcc, so maybe we should ignore
> the broken fallback.
>
> A patch like the attached, perhaps?

Can we update the comment near the top to explain why we need
__UNIQUE_ID() since we've now rediscovered why it was originally
there?

-Kees

--
Kees Cook
Pixel Security

2018-04-09 18:21:05

by Linus Torvalds

[permalink] [raw]
Subject: Re: [bisected] 3c8ba0d61d04ced9f8d9ff93977995a9e4e96e91 oopses on s390

On Mon, Apr 9, 2018 at 11:00 AM, Kees Cook <[email protected]> wrote:
>
> Can we update the comment near the top to explain why we need
> __UNIQUE_ID() since we've now rediscovered why it was originally
> there?

Too late, since it's already committed in my tree and going through
the build test paces.

But I really hope somebody revisits __UNIQUE_ID, and maybe they can
then add a comment to the users too.

It looks like gcc needs at least version 4.3 to have a working
__COUNTER__ implementation. What a coincidence - we don't really
support anything older now anyway.

And similarly for clang - the only versions that didn't have it are
not able to build the kernel anyway.

So we should remove any version conditionals, and we should remove the
known-broken generic fallback that uses __LINE__ instead of
__COUNTER__.

And once you do that, the "prefix" is actually pointlessm and we could
drop it to make __UNIQUE_ID() easier to use.

The *REAL* problem, however, is that __UNIQUE_ID is such a pain to use
in general. You basically have two choices:

- use it as a single-declaration throwaway variable name that is
never actually used

- use it only in a wrapper macro that then passes it off as an
argument to another macro that uses it several times

That "throwaway" use sounds pointless, but it's actually the *common*
use we have for this thing outside of this min/max case. It's used to
shut up the compiler about other unused variables, where people do
things like

static __unused__ __UNIQUE_ID(xyz) = .. mark other variable as used here ..;

and I think the reason it's common is that it's the only *easy* use of
that unique-name-generator macro. Having to pass it off to a second
macro to use as a variable name makes it cumbersome to use for most
normal macro cases.

It would be nice to have the equivalent of __COUNTER__ that just
expanded not to a continually increasing number, but expanded to a
number that expands for each macro expansion.

Then you could do things like

int UNIQUE(a) = (a);

to generate a variable name that was unique within a particular macro
expansion, and then actually _use_ UNIQUE(a) in the same macro
expansion to refer to it without having to pass it off as a name to
another macro that does the declaration and use.

You can't use __UNIQUE_ID() for that, because every new __UNIQUE_ID(a)
will give _another_ unique ID.

(And you *could* use the __LINE__ based one for that, but then you'd
get the whole "nasty shadowing" problem if we have nested macros
again).

Ugh. We have no wonderful model for unique names. Which is why we
obviously just use the "add underscores until it's unique" and the get
it wrong with nesting.

Linus