2018-08-29 02:25:24

by Dmitry Safonov

[permalink] [raw]
Subject: [PATCH 0/4] tty: Hold write ldisc sem in tty_reopen()

Two fixes for potential and real issues.
Looks worth to have in stables as we've hit it on v4.9 stable.
And for linux-next - adding lockdep asserts for line discipline changing
code, verifying that write ldisc sem will be held forthwith.

I couldn't verify that holding write lock fixes the issue as we've hit
it only once and I've failed in reproducing it.
But searching in lkml, Cc'ing here people who probably had the same
crash (and in hope someone of them could give tested-by):

Cc: Daniel Axtens <[email protected]>
Cc: Dmitry Vyukov <[email protected]>
Cc: Michael Neuling <[email protected]>
Cc: Mikulas Patocka <[email protected]>
Cc: Pasi Kärkkäinen <[email protected]>
Cc: Peter Hurley <[email protected]>
Cc: Sergey Senozhatsky <[email protected]>
Cc: Tan Xiaojun <[email protected]>
(please, ignore if I Cc'ed you mistakenly)

Dmitry Safonov (4):
tty: Drop tty->count on tty_reopen() failure
tty: Hold tty_ldisc_lock() during tty_reopen()
tty: Lock tty pair in tty_init_dev()
tty/lockdep: Add ldisc_sem asserts

drivers/tty/tty_io.c | 21 +++++++++++++++------
drivers/tty/tty_ldisc.c | 12 ++++++++----
include/linux/tty.h | 4 ++++
3 files changed, 27 insertions(+), 10 deletions(-)

--
2.13.6



2018-08-29 02:25:24

by Dmitry Safonov

[permalink] [raw]
Subject: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

tty_ldisc_reinit() doesn't race with neither tty_ldisc_hangup()
nor set_ldisc() nor tty_ldisc_release() as they use tty lock.
But it races with anyone who expects line discipline to be the same
after hoding read semaphore in tty_ldisc_ref().

We've seen the following crash on v4.9.108 stable:

BUG: unable to handle kernel paging request at 0000000000002260
IP: [..] n_tty_receive_buf_common+0x5f/0x86d
Workqueue: events_unbound flush_to_ldisc
Call Trace:
[..] n_tty_receive_buf2
[..] tty_ldisc_receive_buf
[..] flush_to_ldisc
[..] process_one_work
[..] worker_thread
[..] kthread
[..] ret_from_fork

I think, tty_ldisc_reinit() should be called with ldisc_sem hold for
writing, which will protect any reader against line discipline changes.

Note: I failed to reproduce the described crash, so obiviously can't
guarantee that this is the place where line discipline was switched.

Cc: Greg Kroah-Hartman <[email protected]>
Cc: Jiri Slaby <[email protected]>
Cc: [email protected]
Signed-off-by: Dmitry Safonov <[email protected]>
---
drivers/tty/tty_io.c | 9 +++++++--
1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/drivers/tty/tty_io.c b/drivers/tty/tty_io.c
index 5e5da9acaf0a..3ef8b977b167 100644
--- a/drivers/tty/tty_io.c
+++ b/drivers/tty/tty_io.c
@@ -1267,15 +1267,20 @@ static int tty_reopen(struct tty_struct *tty)
if (test_bit(TTY_EXCLUSIVE, &tty->flags) && !capable(CAP_SYS_ADMIN))
return -EBUSY;

- tty->count++;
+ retval = tty_ldisc_lock(tty, 5 * HZ);
+ if (retval)
+ return retval;

+ tty->count++;
if (tty->ldisc)
- return 0;
+ goto out_unlock;

retval = tty_ldisc_reinit(tty, tty->termios.c_line);
if (retval)
tty->count--;

+out_unlock:
+ tty_ldisc_unlock(tty);
return retval;
}

--
2.13.6


2018-08-29 02:25:24

by Dmitry Safonov

[permalink] [raw]
Subject: [PATCH 4/4] tty/lockdep: Add ldisc_sem asserts

It should nicely document that each change to line discipline should
held write semaphor. Otherwise potential reader will have a good time.

Cc: Greg Kroah-Hartman <[email protected]>
Cc: Jiri Slaby <[email protected]>
Signed-off-by: Dmitry Safonov <[email protected]>
---
drivers/tty/tty_ldisc.c | 6 ++++++
1 file changed, 6 insertions(+)

diff --git a/drivers/tty/tty_ldisc.c b/drivers/tty/tty_ldisc.c
index b72266461c00..9ef0b33a4132 100644
--- a/drivers/tty/tty_ldisc.c
+++ b/drivers/tty/tty_ldisc.c
@@ -444,6 +444,7 @@ static void tty_set_termios_ldisc(struct tty_struct *tty, int disc)

static int tty_ldisc_open(struct tty_struct *tty, struct tty_ldisc *ld)
{
+ lockdep_assert_held(&tty->ldisc_sem);
WARN_ON(test_and_set_bit(TTY_LDISC_OPEN, &tty->flags));
if (ld->ops->open) {
int ret;
@@ -469,6 +470,7 @@ static int tty_ldisc_open(struct tty_struct *tty, struct tty_ldisc *ld)

static void tty_ldisc_close(struct tty_struct *tty, struct tty_ldisc *ld)
{
+ lockdep_assert_held(&tty->ldisc_sem);
WARN_ON(!test_bit(TTY_LDISC_OPEN, &tty->flags));
clear_bit(TTY_LDISC_OPEN, &tty->flags);
if (ld->ops->close)
@@ -490,6 +492,7 @@ static int tty_ldisc_failto(struct tty_struct *tty, int ld)
struct tty_ldisc *disc = tty_ldisc_get(tty, ld);
int r;

+ lockdep_assert_held(&tty->ldisc_sem);
if (IS_ERR(disc))
return PTR_ERR(disc);
tty->ldisc = disc;
@@ -613,6 +616,7 @@ EXPORT_SYMBOL_GPL(tty_set_ldisc);
*/
static void tty_ldisc_kill(struct tty_struct *tty)
{
+ lockdep_assert_held(&tty->ldisc_sem);
if (!tty->ldisc)
return;
/*
@@ -660,6 +664,7 @@ int tty_ldisc_reinit(struct tty_struct *tty, int disc)
struct tty_ldisc *ld;
int retval;

+ lockdep_assert_held(&tty->ldisc_sem);
ld = tty_ldisc_get(tty, disc);
if (IS_ERR(ld)) {
BUG_ON(disc == N_TTY);
@@ -823,6 +828,7 @@ int tty_ldisc_init(struct tty_struct *tty)
*/
void tty_ldisc_deinit(struct tty_struct *tty)
{
+ /* no ldisc_sem, tty is being destroyed */
if (tty->ldisc)
tty_ldisc_put(tty->ldisc);
tty->ldisc = NULL;
--
2.13.6


2018-08-29 02:25:49

by Dmitry Safonov

[permalink] [raw]
Subject: [PATCH 1/4] tty: Drop tty->count on tty_reopen() failure

In case of tty_ldisc_reinit() failure, tty->count should be decremented
back, otherwise we will never release_tty().
Never seen it in the real life, but it seems not really hard to hit.

Cc: Greg Kroah-Hartman <[email protected]>
Cc: Jiri Slaby <[email protected]>
Cc: [email protected]
Signed-off-by: Dmitry Safonov <[email protected]>
---
drivers/tty/tty_io.c | 11 ++++++++---
1 file changed, 8 insertions(+), 3 deletions(-)

diff --git a/drivers/tty/tty_io.c b/drivers/tty/tty_io.c
index 32bc3e3fe4d3..5e5da9acaf0a 100644
--- a/drivers/tty/tty_io.c
+++ b/drivers/tty/tty_io.c
@@ -1255,6 +1255,7 @@ static void tty_driver_remove_tty(struct tty_driver *driver, struct tty_struct *
static int tty_reopen(struct tty_struct *tty)
{
struct tty_driver *driver = tty->driver;
+ int retval;

if (driver->type == TTY_DRIVER_TYPE_PTY &&
driver->subtype == PTY_TYPE_MASTER)
@@ -1268,10 +1269,14 @@ static int tty_reopen(struct tty_struct *tty)

tty->count++;

- if (!tty->ldisc)
- return tty_ldisc_reinit(tty, tty->termios.c_line);
+ if (tty->ldisc)
+ return 0;

- return 0;
+ retval = tty_ldisc_reinit(tty, tty->termios.c_line);
+ if (retval)
+ tty->count--;
+
+ return retval;
}

/**
--
2.13.6


2018-08-29 02:26:00

by Dmitry Safonov

[permalink] [raw]
Subject: [PATCH 3/4] tty: Lock tty pair in tty_init_dev()

It's safe to not lock both here - done to silence attempt lockdep assert in
tty_ldisc_open(), which will be added with following patch.

Cc: Greg Kroah-Hartman <[email protected]>
Cc: Jiri Slaby <[email protected]>
Signed-off-by: Dmitry Safonov <[email protected]>
---
drivers/tty/tty_io.c | 5 ++---
drivers/tty/tty_ldisc.c | 6 ++----
include/linux/tty.h | 4 ++++
3 files changed, 8 insertions(+), 7 deletions(-)

diff --git a/drivers/tty/tty_io.c b/drivers/tty/tty_io.c
index 3ef8b977b167..a94005f915b3 100644
--- a/drivers/tty/tty_io.c
+++ b/drivers/tty/tty_io.c
@@ -1342,7 +1342,7 @@ struct tty_struct *tty_init_dev(struct tty_driver *driver, int idx)
"%s: %s driver does not set tty->port. This will crash the kernel later. Fix the driver!\n",
__func__, tty->driver->name);

- retval = tty_ldisc_lock(tty, 5 * HZ);
+ retval = tty_ldisc_lock_pair_timeout(tty, tty->link, 5 * HZ);
if (retval)
goto err_release_lock;
tty->port->itty = tty;
@@ -1353,9 +1353,9 @@ struct tty_struct *tty_init_dev(struct tty_driver *driver, int idx)
* to decrement the use counts, as release_tty doesn't care.
*/
retval = tty_ldisc_setup(tty, tty->link);
+ tty_ldisc_unlock_pair(tty, tty->link);
if (retval)
goto err_release_tty;
- tty_ldisc_unlock(tty);
/* Return the tty locked so that it cannot vanish under the caller */
return tty;

@@ -1368,7 +1368,6 @@ struct tty_struct *tty_init_dev(struct tty_driver *driver, int idx)

/* call the tty release_tty routine to clean out this slot */
err_release_tty:
- tty_ldisc_unlock(tty);
tty_info_ratelimited(tty, "ldisc open failed (%d), clearing slot %d\n",
retval, idx);
err_release_lock:
diff --git a/drivers/tty/tty_ldisc.c b/drivers/tty/tty_ldisc.c
index fc4c97cae01e..b72266461c00 100644
--- a/drivers/tty/tty_ldisc.c
+++ b/drivers/tty/tty_ldisc.c
@@ -340,8 +340,7 @@ void tty_ldisc_unlock(struct tty_struct *tty)
__tty_ldisc_unlock(tty);
}

-static int
-tty_ldisc_lock_pair_timeout(struct tty_struct *tty, struct tty_struct *tty2,
+int tty_ldisc_lock_pair_timeout(struct tty_struct *tty, struct tty_struct *tty2,
unsigned long timeout)
{
int ret;
@@ -381,8 +380,7 @@ static void tty_ldisc_lock_pair(struct tty_struct *tty, struct tty_struct *tty2)
tty_ldisc_lock_pair_timeout(tty, tty2, MAX_SCHEDULE_TIMEOUT);
}

-static void tty_ldisc_unlock_pair(struct tty_struct *tty,
- struct tty_struct *tty2)
+void tty_ldisc_unlock_pair(struct tty_struct *tty, struct tty_struct *tty2)
{
__tty_ldisc_unlock(tty);
if (tty2)
diff --git a/include/linux/tty.h b/include/linux/tty.h
index c56e3978b00f..5efb8f87ffdc 100644
--- a/include/linux/tty.h
+++ b/include/linux/tty.h
@@ -409,6 +409,10 @@ extern void tty_kclose(struct tty_struct *tty);
extern int tty_dev_name_to_number(const char *name, dev_t *number);
extern int tty_ldisc_lock(struct tty_struct *tty, unsigned long timeout);
extern void tty_ldisc_unlock(struct tty_struct *tty);
+extern int tty_ldisc_lock_pair_timeout(struct tty_struct *tty,
+ struct tty_struct *tty2, unsigned long timeout);
+extern void tty_ldisc_unlock_pair(struct tty_struct *tty,
+ struct tty_struct *tty2);
#else
static inline void tty_kref_put(struct tty_struct *tty)
{ }
--
2.13.6


2018-08-29 04:36:07

by Sergey Senozhatsky

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

Hi,

Cc-ing Benjamin on this.

On (08/29/18 03:23), Dmitry Safonov wrote:
> BUG: unable to handle kernel paging request at 0000000000002260
> IP: [..] n_tty_receive_buf_common+0x5f/0x86d
> Workqueue: events_unbound flush_to_ldisc
> Call Trace:
> [..] n_tty_receive_buf2
> [..] tty_ldisc_receive_buf
> [..] flush_to_ldisc
> [..] process_one_work
> [..] worker_thread
> [..] kthread
> [..] ret_from_fork

Seems that you are not the first one to hit this NULL deref.

> I think, tty_ldisc_reinit() should be called with ldisc_sem hold for
> writing, which will protect any reader against line discipline changes.

Per https://lore.kernel.org/patchwork/patch/777220/

: Note that we noticed one path that called reinit without the ldisc lock
: held for writing, we added that, but it didn't fix the problem.

And I guess that Ben meant the same reinit path which you patched:

> @@ -1267,15 +1267,20 @@ static int tty_reopen(struct tty_struct *tty)
> if (test_bit(TTY_EXCLUSIVE, &tty->flags) && !capable(CAP_SYS_ADMIN))
> return -EBUSY;
>
> - tty->count++;
> + retval = tty_ldisc_lock(tty, 5 * HZ);
> + if (retval)
> + return retval;
>
> + tty->count++;
> if (tty->ldisc)
> - return 0;
> + goto out_unlock;
>
> retval = tty_ldisc_reinit(tty, tty->termios.c_line);
> if (retval)
> tty->count--;
>
> +out_unlock:
> + tty_ldisc_unlock(tty);
> return retval;
> }

-ss

2018-08-29 14:31:54

by Dmitry Safonov

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

Hi Sergey,

On Wed, 2018-08-29 at 13:34 +0900, Sergey Senozhatsky wrote:
> Hi,
>
> Cc-ing Benjamin on this.

Thanks!

> On (08/29/18 03:23), Dmitry Safonov wrote:
> > BUG: unable to handle kernel paging request at 0000000000002260
> > IP: [..] n_tty_receive_buf_common+0x5f/0x86d
> > Workqueue: events_unbound flush_to_ldisc
> > Call Trace:
> > [..] n_tty_receive_buf2
> > [..] tty_ldisc_receive_buf
> > [..] flush_to_ldisc
> > [..] process_one_work
> > [..] worker_thread
> > [..] kthread
> > [..] ret_from_fork
>
> Seems that you are not the first one to hit this NULL deref.
>
> > I think, tty_ldisc_reinit() should be called with ldisc_sem hold
> > for
> > writing, which will protect any reader against line discipline
> > changes.
>
> Per https://lore.kernel.org/patchwork/patch/777220/
>
> : Note that we noticed one path that called reinit without the ldisc
> lock
> : held for writing, we added that, but it didn't fix the problem.

Probably, it's worth to know what exactly has he tried and what was the
backtrace he got in the result..
Hopefully, we'll hear more.

It might be also worth to review tty_ldisc_deinit(), I thought it's
safe to destroy ldisc there under tty lock during tty release, but may
be that is another non-safe place.

--
Thanks again,
Dmitry

2018-08-29 14:41:02

by Jiri Slaby

[permalink] [raw]
Subject: Re: [PATCH 1/4] tty: Drop tty->count on tty_reopen() failure

On 08/29/2018, 04:23 AM, Dmitry Safonov wrote:
> In case of tty_ldisc_reinit() failure, tty->count should be decremented
> back, otherwise we will never release_tty().
> Never seen it in the real life, but it seems not really hard to hit.

I did see it. And this fixes it.

> Cc: Greg Kroah-Hartman <[email protected]>
> Cc: Jiri Slaby <[email protected]>
> Cc: [email protected]
> Signed-off-by: Dmitry Safonov <[email protected]>
> ---
> drivers/tty/tty_io.c | 11 ++++++++---
> 1 file changed, 8 insertions(+), 3 deletions(-)
>
> diff --git a/drivers/tty/tty_io.c b/drivers/tty/tty_io.c
> index 32bc3e3fe4d3..5e5da9acaf0a 100644
> --- a/drivers/tty/tty_io.c
> +++ b/drivers/tty/tty_io.c
> @@ -1255,6 +1255,7 @@ static void tty_driver_remove_tty(struct tty_driver *driver, struct tty_struct *
> static int tty_reopen(struct tty_struct *tty)
> {
> struct tty_driver *driver = tty->driver;
> + int retval;
>
> if (driver->type == TTY_DRIVER_TYPE_PTY &&
> driver->subtype == PTY_TYPE_MASTER)
> @@ -1268,10 +1269,14 @@ static int tty_reopen(struct tty_struct *tty)
>
> tty->count++;
>
> - if (!tty->ldisc)
> - return tty_ldisc_reinit(tty, tty->termios.c_line);
> + if (tty->ldisc)
> + return 0;
>
> - return 0;
> + retval = tty_ldisc_reinit(tty, tty->termios.c_line);
> + if (retval)
> + tty->count--;

I would just do:
if (!retval)
tty->count++;
here. Nobody from ldiscs should rely on tty->count.

> + return retval;

thanks,
--
js
suse labs

2018-08-29 14:42:25

by Jiri Slaby

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

On 08/29/2018, 04:23 AM, Dmitry Safonov wrote:
> tty_ldisc_reinit() doesn't race with neither tty_ldisc_hangup()
> nor set_ldisc() nor tty_ldisc_release() as they use tty lock.
> But it races with anyone who expects line discipline to be the same
> after hoding read semaphore in tty_ldisc_ref().
>
> We've seen the following crash on v4.9.108 stable:
>
> BUG: unable to handle kernel paging request at 0000000000002260
> IP: [..] n_tty_receive_buf_common+0x5f/0x86d
> Workqueue: events_unbound flush_to_ldisc
> Call Trace:
> [..] n_tty_receive_buf2
> [..] tty_ldisc_receive_buf
> [..] flush_to_ldisc
> [..] process_one_work
> [..] worker_thread
> [..] kthread
> [..] ret_from_fork
>
> I think, tty_ldisc_reinit() should be called with ldisc_sem hold for
> writing, which will protect any reader against line discipline changes.
>
> Note: I failed to reproduce the described crash, so obiviously can't
> guarantee that this is the place where line discipline was switched.
>
> Cc: Greg Kroah-Hartman <[email protected]>
> Cc: Jiri Slaby <[email protected]>
> Cc: [email protected]
> Signed-off-by: Dmitry Safonov <[email protected]>
> ---
> drivers/tty/tty_io.c | 9 +++++++--
> 1 file changed, 7 insertions(+), 2 deletions(-)
>
> diff --git a/drivers/tty/tty_io.c b/drivers/tty/tty_io.c
> index 5e5da9acaf0a..3ef8b977b167 100644
> --- a/drivers/tty/tty_io.c
> +++ b/drivers/tty/tty_io.c
> @@ -1267,15 +1267,20 @@ static int tty_reopen(struct tty_struct *tty)
> if (test_bit(TTY_EXCLUSIVE, &tty->flags) && !capable(CAP_SYS_ADMIN))
> return -EBUSY;
>
> - tty->count++;
> + retval = tty_ldisc_lock(tty, 5 * HZ);

Why 5 secs? This would cause random errors on machines under heavy load.

> + if (retval)
> + return retval;
>
> + tty->count++;
> if (tty->ldisc)
> - return 0;
> + goto out_unlock;
>
> retval = tty_ldisc_reinit(tty, tty->termios.c_line);
> if (retval)
> tty->count--;
>
> +out_unlock:
> + tty_ldisc_unlock(tty);
> return retval;

So what about:
tty_ldisc_lock(tty, MAX_SCHEDULE_TIMEOUT);
if (!tty->ldisc)
ret = tty_ldisc_reinit(tty, tty->termios.c_line);
tty_ldisc_unlock(tty);

if (!ret)
tty->count++;

return ret;

thanks,
--
js
suse labs

2018-08-29 14:47:05

by Jiri Slaby

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

On 08/29/2018, 04:40 PM, Jiri Slaby wrote:
> On 08/29/2018, 04:23 AM, Dmitry Safonov wrote:
>> tty_ldisc_reinit() doesn't race with neither tty_ldisc_hangup()
>> nor set_ldisc() nor tty_ldisc_release() as they use tty lock.
>> But it races with anyone who expects line discipline to be the same
>> after hoding read semaphore in tty_ldisc_ref().
>>
>> We've seen the following crash on v4.9.108 stable:
>>
>> BUG: unable to handle kernel paging request at 0000000000002260
>> IP: [..] n_tty_receive_buf_common+0x5f/0x86d
>> Workqueue: events_unbound flush_to_ldisc
>> Call Trace:
>> [..] n_tty_receive_buf2
>> [..] tty_ldisc_receive_buf
>> [..] flush_to_ldisc
>> [..] process_one_work
>> [..] worker_thread
>> [..] kthread
>> [..] ret_from_fork
>>
>> I think, tty_ldisc_reinit() should be called with ldisc_sem hold for
>> writing, which will protect any reader against line discipline changes.
>>
>> Note: I failed to reproduce the described crash, so obiviously can't
>> guarantee that this is the place where line discipline was switched.

...

> So what about:
> tty_ldisc_lock(tty, MAX_SCHEDULE_TIMEOUT);
> if (!tty->ldisc)
> ret = tty_ldisc_reinit(tty, tty->termios.c_line);
> tty_ldisc_unlock(tty);
>
> if (!ret)
> tty->count++;
>
> return ret;

I forgot to add that I debugged a different NULL ptr deref to this very
same root cause today (set_termios called with NULL tty->disc_data). So
really, tty_reinit's ldisc change must be protected by the ldisc_sem,
otherwise other threads will see tty->ldisc, but not tty->disc_data.

thanks,
--
js
suse labs

2018-08-29 14:48:30

by Jiri Slaby

[permalink] [raw]
Subject: Re: [PATCH 3/4] tty: Lock tty pair in tty_init_dev()

On 08/29/2018, 04:23 AM, Dmitry Safonov wrote:
> It's safe to not lock both here - done to silence attempt lockdep assert in
> tty_ldisc_open(), which will be added with following patch.

SOrry, could you elaborate here? I don't follow...

thanks,
--
js
suse labs

2018-08-29 15:21:05

by Tetsuo Handa

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

On 2018/08/29 11:23, Dmitry Safonov wrote:
> tty_ldisc_reinit() doesn't race with neither tty_ldisc_hangup()
> nor set_ldisc() nor tty_ldisc_release() as they use tty lock.
> But it races with anyone who expects line discipline to be the same
> after hoding read semaphore in tty_ldisc_ref().
>
> We've seen the following crash on v4.9.108 stable:
>
> BUG: unable to handle kernel paging request at 0000000000002260
> IP: [..] n_tty_receive_buf_common+0x5f/0x86d
> Workqueue: events_unbound flush_to_ldisc
> Call Trace:
> [..] n_tty_receive_buf2
> [..] tty_ldisc_receive_buf
> [..] flush_to_ldisc
> [..] process_one_work
> [..] worker_thread
> [..] kthread
> [..] ret_from_fork
>
> I think, tty_ldisc_reinit() should be called with ldisc_sem hold for
> writing, which will protect any reader against line discipline changes.
>
> Note: I failed to reproduce the described crash, so obiviously can't
> guarantee that this is the place where line discipline was switched.

This will be same with a report at
https://syzkaller.appspot.com/bug?id=f08670354701fa64cc0dd3c0128a491bdb16adcc .

syzbot is now testing a patch from Jiri Slaby.

2018-08-29 16:15:03

by Dmitry Safonov

[permalink] [raw]
Subject: Re: [PATCH 1/4] tty: Drop tty->count on tty_reopen() failure

On Wed, 2018-08-29 at 16:38 +0200, Jiri Slaby wrote:
> On 08/29/2018, 04:23 AM, Dmitry Safonov wrote:
> > In case of tty_ldisc_reinit() failure, tty->count should be
> > decremented
> > back, otherwise we will never release_tty().
> > Never seen it in the real life, but it seems not really hard to
> > hit.
>
> I did see it. And this fixes it.

Thanks, I'll add your tested-by, if I'll have to resend.

>
> > Cc: Greg Kroah-Hartman <[email protected]>
> > Cc: Jiri Slaby <[email protected]>
> > Cc: [email protected]
> > Signed-off-by: Dmitry Safonov <[email protected]>
> > ---
> > drivers/tty/tty_io.c | 11 ++++++++---
> > 1 file changed, 8 insertions(+), 3 deletions(-)
> >
> > diff --git a/drivers/tty/tty_io.c b/drivers/tty/tty_io.c
> > index 32bc3e3fe4d3..5e5da9acaf0a 100644
> > --- a/drivers/tty/tty_io.c
> > +++ b/drivers/tty/tty_io.c
> > @@ -1255,6 +1255,7 @@ static void tty_driver_remove_tty(struct
> > tty_driver *driver, struct tty_struct *
> > static int tty_reopen(struct tty_struct *tty)
> > {
> > struct tty_driver *driver = tty->driver;
> > + int retval;
> >
> > if (driver->type == TTY_DRIVER_TYPE_PTY &&
> > driver->subtype == PTY_TYPE_MASTER)
> > @@ -1268,10 +1269,14 @@ static int tty_reopen(struct tty_struct
> > *tty)
> >
> > tty->count++;
> >
> > - if (!tty->ldisc)
> > - return tty_ldisc_reinit(tty, tty->termios.c_line);
> > + if (tty->ldisc)
> > + return 0;
> >
> > - return 0;
> > + retval = tty_ldisc_reinit(tty, tty->termios.c_line);
> > + if (retval)
> > + tty->count--;
>
> I would just do:
> if (!retval)
> tty->count++;
> here. Nobody from ldiscs should rely on tty->count.

I thought about that and probably should have described in commit
message why I haven't done that: I prefer to keep it as was as I did Cc
stable tree - to keep the chance of regression to minimum.

I agree that your way is cleaner, but probably it may be done as
cleanup on top for linux-next..

--
Thanks,
Dmitry

2018-08-29 16:30:11

by Dmitry Safonov

[permalink] [raw]
Subject: Re: [PATCH 3/4] tty: Lock tty pair in tty_init_dev()

On Wed, 2018-08-29 at 16:46 +0200, Jiri Slaby wrote:
> On 08/29/2018, 04:23 AM, Dmitry Safonov wrote:
> > It's safe to not lock both here - done to silence attempt lockdep
> > assert in
> > tty_ldisc_open(), which will be added with following patch.
>
> SOrry, could you elaborate here? I don't follow...

Sure, 4/4 patch adds lockdep_assert_held() into tty_ldisc_open().
Currently ldisc in tty->link isn't locked, which according to code
shouldn't be an issue, as far as I can see.

So, this patch silences lockdep warining by holding the semaphore,
which is slowpath anyway and doesn't case any new contention.

(actually, not holding the semaphore for slave might be an issue if one
opens slave before it's fully initialized, but I'm not sure if it's
possible).

--
Thanks,
Dmitry

2018-08-29 16:38:05

by Dmitry Safonov

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

On Wed, 2018-08-29 at 16:40 +0200, Jiri Slaby wrote:
> On 08/29/2018, 04:23 AM, Dmitry Safonov wrote:
> > tty_ldisc_reinit() doesn't race with neither tty_ldisc_hangup()
> > nor set_ldisc() nor tty_ldisc_release() as they use tty lock.
> > But it races with anyone who expects line discipline to be the same
> > after hoding read semaphore in tty_ldisc_ref().
> >
> > We've seen the following crash on v4.9.108 stable:
> >
> > BUG: unable to handle kernel paging request at 0000000000002260
> > IP: [..] n_tty_receive_buf_common+0x5f/0x86d
> > Workqueue: events_unbound flush_to_ldisc
> > Call Trace:
> > [..] n_tty_receive_buf2
> > [..] tty_ldisc_receive_buf
> > [..] flush_to_ldisc
> > [..] process_one_work
> > [..] worker_thread
> > [..] kthread
> > [..] ret_from_fork
> >
> > I think, tty_ldisc_reinit() should be called with ldisc_sem hold
> > for
> > writing, which will protect any reader against line discipline
> > changes.
> >
> > Note: I failed to reproduce the described crash, so obiviously
> > can't
> > guarantee that this is the place where line discipline was
> > switched.
> >
> > Cc: Greg Kroah-Hartman <[email protected]>
> > Cc: Jiri Slaby <[email protected]>
> > Cc: [email protected]
> > Signed-off-by: Dmitry Safonov <[email protected]>
> > ---
> > drivers/tty/tty_io.c | 9 +++++++--
> > 1 file changed, 7 insertions(+), 2 deletions(-)
> >
> > diff --git a/drivers/tty/tty_io.c b/drivers/tty/tty_io.c
> > index 5e5da9acaf0a..3ef8b977b167 100644
> > --- a/drivers/tty/tty_io.c
> > +++ b/drivers/tty/tty_io.c
> > @@ -1267,15 +1267,20 @@ static int tty_reopen(struct tty_struct
> > *tty)
> > if (test_bit(TTY_EXCLUSIVE, &tty->flags) &&
> > !capable(CAP_SYS_ADMIN))
> > return -EBUSY;
> >
> > - tty->count++;
> > + retval = tty_ldisc_lock(tty, 5 * HZ);
>
> Why 5 secs? This would cause random errors on machines under heavy
> load.

Yeah, I think MAX_SCHEDULE_TIMEOUT will make more sense here..
Not sure, why I decided to go with 5*HZ instead.
Will resend with new timeout, if everything else looks good to you.
(having in mind my argument for count++ in 1/4)

>
> > + if (retval)
> > + return retval;
> >
> > + tty->count++;
> > if (tty->ldisc)
> > - return 0;
> > + goto out_unlock;
> >
> > retval = tty_ldisc_reinit(tty, tty->termios.c_line);
> > if (retval)
> > tty->count--;
> >
> > +out_unlock:
> > + tty_ldisc_unlock(tty);
> > return retval;
>
> So what about:
> tty_ldisc_lock(tty, MAX_SCHEDULE_TIMEOUT);
> if (!tty->ldisc)
> ret = tty_ldisc_reinit(tty, tty->termios.c_line);
> tty_ldisc_unlock(tty);
>
> if (!ret)
> tty->count++;
>
> return ret;
>

--
Thanks,
Dmitry

2018-08-30 05:43:06

by Benjamin Herrenschmidt

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

On Wed, 2018-08-29 at 13:34 +0900, Sergey Senozhatsky wrote:
> Hi,
>
> Cc-ing Benjamin on this.
>
> On (08/29/18 03:23), Dmitry Safonov wrote:
> > BUG: unable to handle kernel paging request at 0000000000002260
> > IP: [..] n_tty_receive_buf_common+0x5f/0x86d
> > Workqueue: events_unbound flush_to_ldisc
> > Call Trace:
> > [..] n_tty_receive_buf2
> > [..] tty_ldisc_receive_buf
> > [..] flush_to_ldisc
> > [..] process_one_work
> > [..] worker_thread
> > [..] kthread
> > [..] ret_from_fork
>
> Seems that you are not the first one to hit this NULL deref.
>
> > I think, tty_ldisc_reinit() should be called with ldisc_sem hold for
> > writing, which will protect any reader against line discipline changes.
>
> Per https://lore.kernel.org/patchwork/patch/777220/
>
> : Note that we noticed one path that called reinit without the ldisc lock
> : held for writing, we added that, but it didn't fix the problem.
>
> And I guess that Ben meant the same reinit path which you patched:

This is too old for me to remember buit yes, there definitely was a bug
there...

> > @@ -1267,15 +1267,20 @@ static int tty_reopen(struct tty_struct *tty)
> > if (test_bit(TTY_EXCLUSIVE, &tty->flags) && !capable(CAP_SYS_ADMIN))
> > return -EBUSY;
> >
> > - tty->count++;
> > + retval = tty_ldisc_lock(tty, 5 * HZ);
> > + if (retval)
> > + return retval;
> >
> > + tty->count++;
> > if (tty->ldisc)
> > - return 0;
> > + goto out_unlock;
> >
> > retval = tty_ldisc_reinit(tty, tty->termios.c_line);
> > if (retval)
> > tty->count--;
> >
> > +out_unlock:
> > + tty_ldisc_unlock(tty);
> > return retval;
> > }
>
> -ss


2018-08-30 07:11:53

by Pasi Kärkkäinen

[permalink] [raw]
Subject: Re: [PATCH 0/4] tty: Hold write ldisc sem in tty_reopen()

Hi Dmitry,

On Wed, Aug 29, 2018 at 03:23:49AM +0100, Dmitry Safonov wrote:
> Two fixes for potential and real issues.
> Looks worth to have in stables as we've hit it on v4.9 stable.
> And for linux-next - adding lockdep asserts for line discipline changing
> code, verifying that write ldisc sem will be held forthwith.
>
> I couldn't verify that holding write lock fixes the issue as we've hit
> it only once and I've failed in reproducing it.
> But searching in lkml, Cc'ing here people who probably had the same
> crash (and in hope someone of them could give tested-by):
>

And thanks a lot for your work on fixing these issues!

I've added Nathan (and centos-virt) to CC, because earlier Nathan was able to reliably trigger ldisc related kernel crash in Xen dom0 when running Linux 4.9 kernel, which seems similar to what your patch 2/4 is trying to fix.

Nathan's kernel crash report: https://lists.centos.org/pipermail/centos-virt/2017-August/005610.html
Example ldisc kernel crash BUG in "n_tty_receive_buf_common": https://lists.centos.org/pipermail/centos-virt/attachments/20170823/45493276/attachment.txt

CentOS bug: https://bugs.centos.org/view.php?id=13713


Thanks,

-- Pasi

> Cc: Daniel Axtens <[email protected]>
> Cc: Dmitry Vyukov <[email protected]>
> Cc: Michael Neuling <[email protected]>
> Cc: Mikulas Patocka <[email protected]>
> Cc: Pasi K?rkk?inen <[email protected]>
> Cc: Peter Hurley <[email protected]>
> Cc: Sergey Senozhatsky <[email protected]>
> Cc: Tan Xiaojun <[email protected]>
> (please, ignore if I Cc'ed you mistakenly)
>
> Dmitry Safonov (4):
> tty: Drop tty->count on tty_reopen() failure
> tty: Hold tty_ldisc_lock() during tty_reopen()
> tty: Lock tty pair in tty_init_dev()
> tty/lockdep: Add ldisc_sem asserts
>
> drivers/tty/tty_io.c | 21 +++++++++++++++------
> drivers/tty/tty_ldisc.c | 12 ++++++++----
> include/linux/tty.h | 4 ++++
> 3 files changed, 27 insertions(+), 10 deletions(-)
>
> --
> 2.13.6
>

2018-08-31 06:50:22

by Jiri Slaby

[permalink] [raw]
Subject: Re: [PATCH 1/4] tty: Drop tty->count on tty_reopen() failure

On 08/29/2018, 06:13 PM, Dmitry Safonov wrote:
>> I would just do:
>> if (!retval)
>> tty->count++;
>> here. Nobody from ldiscs should rely on tty->count.
>
> I thought about that and probably should have described in commit
> message why I haven't done that: I prefer to keep it as was as I did Cc
> stable tree - to keep the chance of regression to minimum.
>
> I agree that your way is cleaner, but probably it may be done as
> cleanup on top for linux-next..

Agreed, so care to cook it up as 5/4 in this series :)?

thanks,
--
js
suse labs

2018-08-31 06:56:10

by Jiri Slaby

[permalink] [raw]
Subject: Re: [PATCH 3/4] tty: Lock tty pair in tty_init_dev()

On 08/29/2018, 06:28 PM, Dmitry Safonov wrote:
> On Wed, 2018-08-29 at 16:46 +0200, Jiri Slaby wrote:
>> On 08/29/2018, 04:23 AM, Dmitry Safonov wrote:
>>> It's safe to not lock both here - done to silence attempt lockdep
>>> assert in
>>> tty_ldisc_open(), which will be added with following patch.
>>
>> SOrry, could you elaborate here? I don't follow...
>
> Sure, 4/4 patch adds lockdep_assert_held() into tty_ldisc_open().
> Currently ldisc in tty->link isn't locked, which according to code
> shouldn't be an issue, as far as I can see.
>
> So, this patch silences lockdep warining by holding the semaphore,
> which is slowpath anyway and doesn't case any new contention.

Eh, no... Adding a lock just to make lockdep happy is a no-go. The
locking in tty is already complex enough.

> (actually, not holding the semaphore for slave might be an issue if one
> opens slave before it's fully initialized, but I'm not sure if it's
> possible).

If that turns out to be a problem, we can apply the patch. BUt unless it
is proven to be so (be it code review or a reproducer), let's leave the
locking as it is.

thanks,
--
js
suse labs

2018-08-31 07:02:54

by Jiri Slaby

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

On 08/29/2018, 05:19 PM, Tetsuo Handa wrote:
> On 2018/08/29 11:23, Dmitry Safonov wrote:
>> tty_ldisc_reinit() doesn't race with neither tty_ldisc_hangup()
>> nor set_ldisc() nor tty_ldisc_release() as they use tty lock.
>> But it races with anyone who expects line discipline to be the same
>> after hoding read semaphore in tty_ldisc_ref().
>>
>> We've seen the following crash on v4.9.108 stable:
>>
>> BUG: unable to handle kernel paging request at 0000000000002260
>> IP: [..] n_tty_receive_buf_common+0x5f/0x86d
>> Workqueue: events_unbound flush_to_ldisc
>> Call Trace:
>> [..] n_tty_receive_buf2
>> [..] tty_ldisc_receive_buf
>> [..] flush_to_ldisc
>> [..] process_one_work
>> [..] worker_thread
>> [..] kthread
>> [..] ret_from_fork
>>
>> I think, tty_ldisc_reinit() should be called with ldisc_sem hold for
>> writing, which will protect any reader against line discipline changes.
>>
>> Note: I failed to reproduce the described crash, so obiviously can't
>> guarantee that this is the place where line discipline was switched.
>
> This will be same with a report at
> https://syzkaller.appspot.com/bug?id=f08670354701fa64cc0dd3c0128a491bdb16adcc .
>
> syzbot is now testing a patch from Jiri Slaby.

Yes, my patch passed, so could you add:
Reported-by: [email protected]

(not adding tested-by as this particular patch was not tested, but
shoiuld work the same way.)

thanks,
--
js
suse labs

2018-08-31 11:21:10

by Tetsuo Handa

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

On 2018/08/31 15:51, Jiri Slaby wrote:
> On 08/29/2018, 05:19 PM, Tetsuo Handa wrote:
>> On 2018/08/29 11:23, Dmitry Safonov wrote:
>>> tty_ldisc_reinit() doesn't race with neither tty_ldisc_hangup()
>>> nor set_ldisc() nor tty_ldisc_release() as they use tty lock.
>>> But it races with anyone who expects line discipline to be the same
>>> after hoding read semaphore in tty_ldisc_ref().
>>>
>>> We've seen the following crash on v4.9.108 stable:
>>>
>>> BUG: unable to handle kernel paging request at 0000000000002260
>>> IP: [..] n_tty_receive_buf_common+0x5f/0x86d
>>> Workqueue: events_unbound flush_to_ldisc
>>> Call Trace:
>>> [..] n_tty_receive_buf2
>>> [..] tty_ldisc_receive_buf
>>> [..] flush_to_ldisc
>>> [..] process_one_work
>>> [..] worker_thread
>>> [..] kthread
>>> [..] ret_from_fork
>>>
>>> I think, tty_ldisc_reinit() should be called with ldisc_sem hold for
>>> writing, which will protect any reader against line discipline changes.
>>>
>>> Note: I failed to reproduce the described crash, so obiviously can't
>>> guarantee that this is the place where line discipline was switched.
>>
>> This will be same with a report at
>> https://syzkaller.appspot.com/bug?id=f08670354701fa64cc0dd3c0128a491bdb16adcc .
>>
>> syzbot is now testing a patch from Jiri Slaby.
>
> Yes, my patch passed, so could you add:
> Reported-by: [email protected]
>
> (not adding tested-by as this particular patch was not tested, but
> shoiuld work the same way.)
>
> thanks,
>

Tested with all 4 patches applied using syzbot-provided reproducer and
my simplified reproducer. No crashes and no lockdep warnings.
Also, noisy messages like

pts pts4033: tty_release: tty->count(10529) != (#fd's(7) + #kopen's(0))

are gone. Very nice. Thank you.

2018-08-31 12:14:43

by Dmitry Safonov

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

On Fri, 2018-08-31 at 13:21 +0200, Jiri Slaby wrote:
> On 08/31/2018, 01:17 PM, Tetsuo Handa wrote:
> > Also, noisy messages like
> >
> > pts pts4033: tty_release: tty->count(10529) != (#fd's(7) +
> > #kopen's(0))
> >
> > are gone.
>
> fwiw, thanks to 1/4…
>
> Dmitry, could you note the message above to the commit log of 1/4, so
> that we know the patch fixed that and downstream can pick it up...
>

Sure, will do.

--
Thanks,
Dmitry

2018-08-31 12:24:12

by Dmitry Safonov

[permalink] [raw]
Subject: Re: [PATCH 3/4] tty: Lock tty pair in tty_init_dev()

On Fri, 2018-08-31 at 08:54 +0200, Jiri Slaby wrote:
> On 08/29/2018, 06:28 PM, Dmitry Safonov wrote:
> > On Wed, 2018-08-29 at 16:46 +0200, Jiri Slaby wrote:
> > > On 08/29/2018, 04:23 AM, Dmitry Safonov wrote:
> > > > It's safe to not lock both here - done to silence attempt
> > > > lockdep
> > > > assert in
> > > > tty_ldisc_open(), which will be added with following patch.
> > >
> > > SOrry, could you elaborate here? I don't follow...
> >
> > Sure, 4/4 patch adds lockdep_assert_held() into tty_ldisc_open().
> > Currently ldisc in tty->link isn't locked, which according to code
> > shouldn't be an issue, as far as I can see.
> >
> > So, this patch silences lockdep warining by holding the semaphore,
> > which is slowpath anyway and doesn't case any new contention.
>
> Eh, no... Adding a lock just to make lockdep happy is a no-go. The
> locking in tty is already complex enough.
>
> > (actually, not holding the semaphore for slave might be an issue if
> > one
> > opens slave before it's fully initialized, but I'm not sure if it's
> > possible).
>
> If that turns out to be a problem, we can apply the patch. BUt unless
> it
> is proven to be so (be it code review or a reproducer), let's leave
> the
> locking as it is.

Ok, than for v2 I'll just remove lockdep_assert() from
tty_ldisc_open().

--
Thanks,
Dmitry

2018-08-31 12:46:30

by Jiri Slaby

[permalink] [raw]
Subject: Re: [PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()

On 08/31/2018, 01:17 PM, Tetsuo Handa wrote:
> Also, noisy messages like
>
> pts pts4033: tty_release: tty->count(10529) != (#fd's(7) + #kopen's(0))
>
> are gone.

fwiw, thanks to 1/4…

Dmitry, could you note the message above to the commit log of 1/4, so
that we know the patch fixed that and downstream can pick it up...

--
js
suse labs

2018-08-31 12:55:22

by Dmitry Safonov

[permalink] [raw]
Subject: Re: [PATCH 1/4] tty: Drop tty->count on tty_reopen() failure

On Fri, 2018-08-31 at 08:47 +0200, Jiri Slaby wrote:
> On 08/29/2018, 06:13 PM, Dmitry Safonov wrote:
> > > I would just do:
> > > if (!retval)
> > > tty->count++;
> > > here. Nobody from ldiscs should rely on tty->count.
> >
> > I thought about that and probably should have described in commit
> > message why I haven't done that: I prefer to keep it as was as I
> > did Cc
> > stable tree - to keep the chance of regression to minimum.
> >
> > I agree that your way is cleaner, but probably it may be done as
> > cleanup on top for linux-next..
>
> Agreed, so care to cook it up as 5/4 in this series :)?

Sure, will resend v2 with that and all tested-by.

--
Thanks,
Dmitry

2018-09-07 05:36:46

by Chen, Rong A

[permalink] [raw]
Subject: [LKP] [tty] 0b4f83d510: INFO:task_blocked_for_more_than#seconds

FYI, we noticed the following commit (built with gcc-7):

commit: 0b4f83d510f6fef6bb9da25f122c8d733d50516f ("[PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()")
url: https://github.com/0day-ci/linux/commits/Dmitry-Safonov/tty-Hold-write-ldisc-sem-in-tty_reopen/20180829-165618
base: https://git.kernel.org/cgit/linux/kernel/git/gregkh/tty.git tty-testing

in testcase: trinity
with following parameters:

runtime: 300s

test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/


on test machine: qemu-system-x86_64 -enable-kvm -m 256M

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+--------------------------------------------------+------------+------------+
| | 58dd163974 | 0b4f83d510 |
+--------------------------------------------------+------------+------------+
| boot_successes | 14 | 4 |
| boot_failures | 0 | 6 |
| INFO:task_blocked_for_more_than#seconds | 0 | 6 |
| Kernel_panic-not_syncing:hung_task:blocked_tasks | 0 | 6 |
+--------------------------------------------------+------------+------------+



[ 244.816801] INFO: task validate_data:655 blocked for more than 120 seconds.
[ 244.818833] Not tainted 4.18.0-11684-g0b4f83d #1
[ 244.820028] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 244.826965] validate_data D 0 655 623 0x20020000
[ 244.828279] Call Trace:
[ 244.828958] ? __schedule+0x843/0x950
[ 244.830173] ? __ldsem_down_read_nested+0x1c4/0x3b0
[ 244.834903] schedule+0x31/0x70
[ 244.835665] schedule_timeout+0x34/0x760
[ 244.836613] ? ftrace_likely_update+0x35/0x60
[ 244.837683] ? __ldsem_down_read_nested+0x1c4/0x3b0
[ 244.838818] ? ftrace_likely_update+0x35/0x60
[ 244.840127] ? ftrace_likely_update+0x35/0x60
[ 244.845947] ? __ldsem_down_read_nested+0x1c4/0x3b0
[ 244.847882] __ldsem_down_read_nested+0x23a/0x3b0
[ 244.849886] ? tty_ldisc_ref_wait+0x25/0x50
[ 244.853807] tty_ldisc_ref_wait+0x25/0x50
[ 244.854946] tty_compat_ioctl+0x8a/0x120
[ 244.855928] ? this_tty+0x80/0x80
[ 244.856742] __ia32_compat_sys_ioctl+0xc28/0x1ce0
[ 244.857981] do_int80_syscall_32+0x1d2/0x5f0
[ 244.859003] entry_INT80_compat+0x88/0xa0
[ 244.859972] INFO: task dnsmasq:668 blocked for more than 120 seconds.
[ 244.868315] Not tainted 4.18.0-11684-g0b4f83d #1
[ 244.869583] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 244.871744] dnsmasq D 0 668 1 0x20020000
[ 244.873063] Call Trace:
[ 244.873697] ? __schedule+0x843/0x950
[ 244.874572] ? __ldsem_down_read_nested+0x1c4/0x3b0
[ 244.875725] schedule+0x31/0x70
[ 244.876576] schedule_timeout+0x34/0x760
[ 244.877573] ? ftrace_likely_update+0x35/0x60
[ 244.878660] ? __ldsem_down_read_nested+0x1c4/0x3b0
[ 244.879872] ? ftrace_likely_update+0x35/0x60
[ 244.890522] ? ftrace_likely_update+0x35/0x60
[ 244.891572] ? __ldsem_down_read_nested+0x1c4/0x3b0
[ 244.892746] __ldsem_down_read_nested+0x23a/0x3b0
[ 244.893861] ? tty_ldisc_ref_wait+0x25/0x50
[ 244.894841] tty_ldisc_ref_wait+0x25/0x50
[ 244.895911] tty_compat_ioctl+0x8a/0x120
[ 244.896916] ? this_tty+0x80/0x80
[ 244.897717] __ia32_compat_sys_ioctl+0xc28/0x1ce0
[ 244.898821] do_int80_syscall_32+0x1d2/0x5f0
[ 244.899830] entry_INT80_compat+0x88/0xa0
[ 244.909466] INFO: task dropbear:734 blocked for more than 120 seconds.
[ 244.911173] Not tainted 4.18.0-11684-g0b4f83d #1
[ 244.912394] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 244.914176] dropbear D 0 734 1 0x20020000
[ 244.915446] Call Trace:
[ 244.916068] ? __schedule+0x843/0x950
[ 244.916945] ? __ldsem_down_read_nested+0x1c4/0x3b0
[ 244.918076] schedule+0x31/0x70
[ 244.918832] schedule_timeout+0x34/0x760
[ 244.919781] ? ftrace_likely_update+0x35/0x60
[ 244.921104] ? __ldsem_down_read_nested+0x1c4/0x3b0
[ 244.922304] ? ftrace_likely_update+0x35/0x60
[ 244.923347] ? ftrace_likely_update+0x35/0x60
[ 244.924369] ? __ldsem_down_read_nested+0x1c4/0x3b0
[ 244.925496] __ldsem_down_read_nested+0x23a/0x3b0
[ 244.926598] ? tty_ldisc_ref_wait+0x25/0x50
[ 244.927578] tty_ldisc_ref_wait+0x25/0x50
[ 244.928526] tty_compat_ioctl+0x8a/0x120
[ 244.929449] ? this_tty+0x80/0x80
[ 244.930240] __ia32_compat_sys_ioctl+0xc28/0x1ce0
[ 244.940083] do_int80_syscall_32+0x1d2/0x5f0
[ 244.941310] entry_INT80_compat+0x88/0xa0
[ 244.944070]
[ 244.944070] Showing all locks held in the system:
[ 244.945558] 1 lock held by khungtaskd/18:
[ 244.946495] #0: (____ptrval____) (rcu_read_lock){....}, at: debug_show_all_locks+0x16/0x190
[ 244.948503] 2 locks held by askfirst/235:
[ 244.949439] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
[ 244.951762] #1: (____ptrval____) (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x13d/0xa00
[ 244.953799] 1 lock held by validate_data/655:
[ 244.954814] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
[ 244.956764] 1 lock held by dnsmasq/668:
[ 244.957649] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
[ 244.959598] 1 lock held by dropbear/734:
[ 244.967564] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
[ 244.969581]
[ 244.969975] =============================================
[ 244.969975]
[ 244.971833] NMI backtrace for cpu 0
[ 244.972696] CPU: 0 PID: 18 Comm: khungtaskd Not tainted 4.18.0-11684-g0b4f83d #1
[ 244.974371] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 244.976260] Call Trace:
[ 244.976895] dump_stack+0xb9/0x10e
[ 244.977723] ? lapic_can_unplug_cpu+0xa0/0xa0
[ 244.978735] nmi_cpu_backtrace+0x13a/0x150
[ 244.979697] ? lapic_can_unplug_cpu+0xa0/0xa0
[ 244.980713] nmi_trigger_cpumask_backtrace+0x188/0x280
[ 244.981899] watchdog+0x83b/0x880
[ 244.982683] ? reset_hung_task_detector+0x20/0x20
[ 244.983762] kthread+0x170/0x180
[ 244.984509] ? kthread_create_worker_on_cpu+0x70/0x70
[ 244.985659] ret_from_fork+0x24/0x30
[ 244.990807] Kernel panic - not syncing: hung_task: blocked tasks
[ 244.992205] CPU: 0 PID: 18 Comm: khungtaskd Not tainted 4.18.0-11684-g0b4f83d #1
[ 244.993881] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 244.995769] Call Trace:
[ 244.996362] dump_stack+0xb9/0x10e
[ 244.997166] panic+0xfd/0x2bb
[ 244.997878] ? nmi_trigger_cpumask_backtrace+0x269/0x280
[ 244.999097] ? watchdog+0x83b/0x880
[ 244.999982] watchdog+0x847/0x880
[ 245.000782] ? reset_hung_task_detector+0x20/0x20
[ 245.001862] kthread+0x170/0x180
[ 245.002613] ? kthread_create_worker_on_cpu+0x70/0x70
[ 245.003785] ret_from_fork+0x24/0x30
[ 245.004646] Kernel Offset: 0x10800000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[ 245.007065] Rebooting in 3 seconds..

Elapsed time: 250

#!/bin/bash

# To reproduce,
# 1) save job-script and this script (both are attached in 0day report email)
# 2) run this script with your compiled kernel and optional env $INSTALL_MOD_PATH

kernel=$1

initrds=(
/osimage/openwrt/openwrt-i386-2016-03-16.cgz
/lkp/lkp/lkp-i386.cgz
/osimage/pkg/debian-x86_64-2016-08-31.cgz/trinity-static-i386-x86_64-6ddabfd2_2017-11-10.cgz
)

HTTP_PREFIX=https://download.01.org/0day-ci/lkp-qemu
wget --timestamping "${initrds[@]/#/$HTTP_PREFIX}"

{
cat "${initrds[@]//*\//}"
[[ $INSTALL_MOD_PATH ]] && (
cd "$INSTALL_MOD_PATH"
find lib | cpio -o -H newc --quiet | gzip
)
echo job-script | cpio -o -H newc --quiet | gzip
} > initrd.img

qemu-img create -f qcow2 disk-vm-lkp-hsw-4ep1-openwrt-ia32-13-0 256G
qemu-img create -f qcow2 disk-vm-lkp-hsw-4ep1-openwrt-ia32-13-1 256G

kvm=(
qemu-system-x86_64


To reproduce:

git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email



Thanks,
Rong, Chen


Attachments:
(No filename) (8.23 kB)
config-4.18.0-11684-g0b4f83d (88.78 kB)
job-script (4.08 kB)
dmesg.xz (17.43 kB)
Download all attachments

2018-09-07 06:43:48

by Jiri Slaby

[permalink] [raw]
Subject: Re: [LKP] [tty] 0b4f83d510: INFO:task_blocked_for_more_than#seconds

On 09/07/2018, 06:50 AM, kernel test robot wrote:
> FYI, we noticed the following commit (built with gcc-7):
>
> commit: 0b4f83d510f6fef6bb9da25f122c8d733d50516f ("[PATCH 2/4] tty: Hold tty_ldisc_lock() during tty_reopen()")
> url: https://github.com/0day-ci/linux/commits/Dmitry-Safonov/tty-Hold-write-ldisc-sem-in-tty_reopen/20180829-165618
> base: https://git.kernel.org/cgit/linux/kernel/git/gregkh/tty.git tty-testing
>
> in testcase: trinity
> with following parameters:
>
> runtime: 300s
>
> test-description: Trinity is a linux system call fuzz tester.
> test-url: http://codemonkey.org.uk/projects/trinity/
>
>
> on test machine: qemu-system-x86_64 -enable-kvm -m 256M
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>
>
> +--------------------------------------------------+------------+------------+
> | | 58dd163974 | 0b4f83d510 |
> +--------------------------------------------------+------------+------------+
> | boot_successes | 14 | 4 |
> | boot_failures | 0 | 6 |
> | INFO:task_blocked_for_more_than#seconds | 0 | 6 |
> | Kernel_panic-not_syncing:hung_task:blocked_tasks | 0 | 6 |
> +--------------------------------------------------+------------+------------+
>
>
>
> [ 244.816801] INFO: task validate_data:655 blocked for more than 120 seconds.
> [ 244.818833] Not tainted 4.18.0-11684-g0b4f83d #1
> [ 244.820028] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 244.826965] validate_data D 0 655 623 0x20020000
> [ 244.828279] Call Trace:
> [ 244.828958] ? __schedule+0x843/0x950
> [ 244.830173] ? __ldsem_down_read_nested+0x1c4/0x3b0
> [ 244.834903] schedule+0x31/0x70
> [ 244.835665] schedule_timeout+0x34/0x760
> [ 244.836613] ? ftrace_likely_update+0x35/0x60
> [ 244.837683] ? __ldsem_down_read_nested+0x1c4/0x3b0
> [ 244.838818] ? ftrace_likely_update+0x35/0x60
> [ 244.840127] ? ftrace_likely_update+0x35/0x60
> [ 244.845947] ? __ldsem_down_read_nested+0x1c4/0x3b0
> [ 244.847882] __ldsem_down_read_nested+0x23a/0x3b0
> [ 244.849886] ? tty_ldisc_ref_wait+0x25/0x50
> [ 244.853807] tty_ldisc_ref_wait+0x25/0x50
> [ 244.854946] tty_compat_ioctl+0x8a/0x120
> [ 244.855928] ? this_tty+0x80/0x80
> [ 244.856742] __ia32_compat_sys_ioctl+0xc28/0x1ce0
> [ 244.857981] do_int80_syscall_32+0x1d2/0x5f0
> [ 244.859003] entry_INT80_compat+0x88/0xa0
> [ 244.859972] INFO: task dnsmasq:668 blocked for more than 120 seconds.
> [ 244.868315] Not tainted 4.18.0-11684-g0b4f83d #1
> [ 244.869583] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 244.871744] dnsmasq D 0 668 1 0x20020000
> [ 244.873063] Call Trace:
> [ 244.873697] ? __schedule+0x843/0x950
> [ 244.874572] ? __ldsem_down_read_nested+0x1c4/0x3b0
> [ 244.875725] schedule+0x31/0x70
> [ 244.876576] schedule_timeout+0x34/0x760
> [ 244.877573] ? ftrace_likely_update+0x35/0x60
> [ 244.878660] ? __ldsem_down_read_nested+0x1c4/0x3b0
> [ 244.879872] ? ftrace_likely_update+0x35/0x60
> [ 244.890522] ? ftrace_likely_update+0x35/0x60
> [ 244.891572] ? __ldsem_down_read_nested+0x1c4/0x3b0
> [ 244.892746] __ldsem_down_read_nested+0x23a/0x3b0
> [ 244.893861] ? tty_ldisc_ref_wait+0x25/0x50
> [ 244.894841] tty_ldisc_ref_wait+0x25/0x50
> [ 244.895911] tty_compat_ioctl+0x8a/0x120
> [ 244.896916] ? this_tty+0x80/0x80
> [ 244.897717] __ia32_compat_sys_ioctl+0xc28/0x1ce0
> [ 244.898821] do_int80_syscall_32+0x1d2/0x5f0
> [ 244.899830] entry_INT80_compat+0x88/0xa0
> [ 244.909466] INFO: task dropbear:734 blocked for more than 120 seconds.
> [ 244.911173] Not tainted 4.18.0-11684-g0b4f83d #1
> [ 244.912394] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 244.914176] dropbear D 0 734 1 0x20020000
> [ 244.915446] Call Trace:
> [ 244.916068] ? __schedule+0x843/0x950
> [ 244.916945] ? __ldsem_down_read_nested+0x1c4/0x3b0
> [ 244.918076] schedule+0x31/0x70
> [ 244.918832] schedule_timeout+0x34/0x760
> [ 244.919781] ? ftrace_likely_update+0x35/0x60
> [ 244.921104] ? __ldsem_down_read_nested+0x1c4/0x3b0
> [ 244.922304] ? ftrace_likely_update+0x35/0x60
> [ 244.923347] ? ftrace_likely_update+0x35/0x60
> [ 244.924369] ? __ldsem_down_read_nested+0x1c4/0x3b0
> [ 244.925496] __ldsem_down_read_nested+0x23a/0x3b0
> [ 244.926598] ? tty_ldisc_ref_wait+0x25/0x50
> [ 244.927578] tty_ldisc_ref_wait+0x25/0x50
> [ 244.928526] tty_compat_ioctl+0x8a/0x120
> [ 244.929449] ? this_tty+0x80/0x80
> [ 244.930240] __ia32_compat_sys_ioctl+0xc28/0x1ce0
> [ 244.940083] do_int80_syscall_32+0x1d2/0x5f0
> [ 244.941310] entry_INT80_compat+0x88/0xa0
> [ 244.944070]
> [ 244.944070] Showing all locks held in the system:
> [ 244.945558] 1 lock held by khungtaskd/18:
> [ 244.946495] #0: (____ptrval____) (rcu_read_lock){....}, at: debug_show_all_locks+0x16/0x190
> [ 244.948503] 2 locks held by askfirst/235:
> [ 244.949439] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
> [ 244.951762] #1: (____ptrval____) (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x13d/0xa00

Here, it just seems to wait for input from the user.

> [ 244.953799] 1 lock held by validate_data/655:
> [ 244.954814] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
> [ 244.956764] 1 lock held by dnsmasq/668:
> [ 244.957649] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
> [ 244.959598] 1 lock held by dropbear/734:
> [ 244.967564] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50

Hmm, I assume there is another task waiting for write_ldsem and that one
prevents these readers to proceed. Unfortunately, due to the defunct
__ptrval__ pointer hashing crap, we do not see who is waiting for what.
But I am guessing all are the same locks.

So I think, we are forced to limit the waiting to 5 seconds in reopen in
the end too (the same as we do for new open in tty_init_dev).

Dmitry, could you add the limit and handle the return value of
tty_ldisc_lock now?

thanks,
--
js
suse labs

2018-09-07 14:35:37

by Dmitry Safonov

[permalink] [raw]
Subject: Re: [LKP] [tty] 0b4f83d510: INFO:task_blocked_for_more_than#seconds

On Fri, 2018-09-07 at 08:39 +0200, Jiri Slaby wrote:
> On 09/07/2018, 06:50 AM, kernel test robot wrote:
> > FYI, we noticed the following commit (built with gcc-7):
> >
> > commit: 0b4f83d510f6fef6bb9da25f122c8d733d50516f ("[PATCH 2/4] tty:
> > Hold tty_ldisc_lock() during tty_reopen()")
> > url: https://github.com/0day-ci/linux/commits/Dmitry-Safonov/tty-Ho
> > ld-write-ldisc-sem-in-tty_reopen/20180829-165618
> > base: https://git.kernel.org/cgit/linux/kernel/git/gregkh/tty.git
> > tty-testing
> >
> > in testcase: trinity
> > with following parameters:
> >
> > runtime: 300s
> >
> > test-description: Trinity is a linux system call fuzz tester.
> > test-url: http://codemonkey.org.uk/projects/trinity/
> >
> >
> > on test machine: qemu-system-x86_64 -enable-kvm -m 256M
> >
> > caused below changes (please refer to attached dmesg/kmsg for
> > entire log/backtrace):
> >
> >
> > +--------------------------------------------------+------------+
> > ------------+
> > > | 58dd163974 |
> > > 0b4f83d510 |
> >
> > +--------------------------------------------------+------------+
> > ------------+
> > > boot_successes | 14 |
> > > 4 |
> > > boot_failures | 0 |
> > > 6 |
> > > INFO:task_blocked_for_more_than#seconds | 0 |
> > > 6 |
> > > Kernel_panic-not_syncing:hung_task:blocked_tasks | 0 |
> > > 6 |
> >
> > +--------------------------------------------------+------------+
> > ------------+
> >
> >
> >
> > [ 244.816801] INFO: task validate_data:655 blocked for more than
> > 120 seconds.
> > [ 244.818833] Not tainted 4.18.0-11684-g0b4f83d #1
> > [ 244.820028] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > disables this message.
> > [ 244.826965] validate_data D 0 655 623 0x20020000
> > [ 244.828279] Call Trace:
> > [ 244.828958] ? __schedule+0x843/0x950
> > [ 244.830173] ? __ldsem_down_read_nested+0x1c4/0x3b0
> > [ 244.834903] schedule+0x31/0x70
> > [ 244.835665] schedule_timeout+0x34/0x760
> > [ 244.836613] ? ftrace_likely_update+0x35/0x60
> > [ 244.837683] ? __ldsem_down_read_nested+0x1c4/0x3b0
> > [ 244.838818] ? ftrace_likely_update+0x35/0x60
> > [ 244.840127] ? ftrace_likely_update+0x35/0x60
> > [ 244.845947] ? __ldsem_down_read_nested+0x1c4/0x3b0
> > [ 244.847882] __ldsem_down_read_nested+0x23a/0x3b0
> > [ 244.849886] ? tty_ldisc_ref_wait+0x25/0x50
> > [ 244.853807] tty_ldisc_ref_wait+0x25/0x50
> > [ 244.854946] tty_compat_ioctl+0x8a/0x120
> > [ 244.855928] ? this_tty+0x80/0x80
> > [ 244.856742] __ia32_compat_sys_ioctl+0xc28/0x1ce0
> > [ 244.857981] do_int80_syscall_32+0x1d2/0x5f0
> > [ 244.859003] entry_INT80_compat+0x88/0xa0
> > [ 244.859972] INFO: task dnsmasq:668 blocked for more than 120
> > seconds.
> > [ 244.868315] Not tainted 4.18.0-11684-g0b4f83d #1
> > [ 244.869583] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > disables this message.
> > [ 244.871744] dnsmasq D 0 668 1 0x20020000
> > [ 244.873063] Call Trace:
> > [ 244.873697] ? __schedule+0x843/0x950
> > [ 244.874572] ? __ldsem_down_read_nested+0x1c4/0x3b0
> > [ 244.875725] schedule+0x31/0x70
> > [ 244.876576] schedule_timeout+0x34/0x760
> > [ 244.877573] ? ftrace_likely_update+0x35/0x60
> > [ 244.878660] ? __ldsem_down_read_nested+0x1c4/0x3b0
> > [ 244.879872] ? ftrace_likely_update+0x35/0x60
> > [ 244.890522] ? ftrace_likely_update+0x35/0x60
> > [ 244.891572] ? __ldsem_down_read_nested+0x1c4/0x3b0
> > [ 244.892746] __ldsem_down_read_nested+0x23a/0x3b0
> > [ 244.893861] ? tty_ldisc_ref_wait+0x25/0x50
> > [ 244.894841] tty_ldisc_ref_wait+0x25/0x50
> > [ 244.895911] tty_compat_ioctl+0x8a/0x120
> > [ 244.896916] ? this_tty+0x80/0x80
> > [ 244.897717] __ia32_compat_sys_ioctl+0xc28/0x1ce0
> > [ 244.898821] do_int80_syscall_32+0x1d2/0x5f0
> > [ 244.899830] entry_INT80_compat+0x88/0xa0
> > [ 244.909466] INFO: task dropbear:734 blocked for more than 120
> > seconds.
> > [ 244.911173] Not tainted 4.18.0-11684-g0b4f83d #1
> > [ 244.912394] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > disables this message.
> > [ 244.914176] dropbear D 0 734 1 0x20020000
> > [ 244.915446] Call Trace:
> > [ 244.916068] ? __schedule+0x843/0x950
> > [ 244.916945] ? __ldsem_down_read_nested+0x1c4/0x3b0
> > [ 244.918076] schedule+0x31/0x70
> > [ 244.918832] schedule_timeout+0x34/0x760
> > [ 244.919781] ? ftrace_likely_update+0x35/0x60
> > [ 244.921104] ? __ldsem_down_read_nested+0x1c4/0x3b0
> > [ 244.922304] ? ftrace_likely_update+0x35/0x60
> > [ 244.923347] ? ftrace_likely_update+0x35/0x60
> > [ 244.924369] ? __ldsem_down_read_nested+0x1c4/0x3b0
> > [ 244.925496] __ldsem_down_read_nested+0x23a/0x3b0
> > [ 244.926598] ? tty_ldisc_ref_wait+0x25/0x50
> > [ 244.927578] tty_ldisc_ref_wait+0x25/0x50
> > [ 244.928526] tty_compat_ioctl+0x8a/0x120
> > [ 244.929449] ? this_tty+0x80/0x80
> > [ 244.930240] __ia32_compat_sys_ioctl+0xc28/0x1ce0
> > [ 244.940083] do_int80_syscall_32+0x1d2/0x5f0
> > [ 244.941310] entry_INT80_compat+0x88/0xa0
> > [ 244.944070]
> > [ 244.944070] Showing all locks held in the system:
> > [ 244.945558] 1 lock held by khungtaskd/18:
> > [ 244.946495] #0: (____ptrval____) (rcu_read_lock){....}, at:
> > debug_show_all_locks+0x16/0x190
> > [ 244.948503] 2 locks held by askfirst/235:
> > [ 244.949439] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at:
> > tty_ldisc_ref_wait+0x25/0x50
> > [ 244.951762] #1: (____ptrval____) (&ldata-
> > >atomic_read_lock){+.+.}, at: n_tty_read+0x13d/0xa00
>
> Here, it just seems to wait for input from the user.
>
> > [ 244.953799] 1 lock held by validate_data/655:
> > [ 244.954814] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at:
> > tty_ldisc_ref_wait+0x25/0x50
> > [ 244.956764] 1 lock held by dnsmasq/668:
> > [ 244.957649] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at:
> > tty_ldisc_ref_wait+0x25/0x50
> > [ 244.959598] 1 lock held by dropbear/734:
> > [ 244.967564] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at:
> > tty_ldisc_ref_wait+0x25/0x50
>
> Hmm, I assume there is another task waiting for write_ldsem and that
> one
> prevents these readers to proceed. Unfortunately, due to the defunct
> __ptrval__ pointer hashing crap, we do not see who is waiting for
> what.
> But I am guessing all are the same locks.

Hmm, and the writer is not able to grab it because there is already
reader who uses console, I suppose.
I wonder if we can add re-acquiring for the reader side..
That will make write acquire less likely to fail under the load.
I'll try to reproduce it.

>
> So I think, we are forced to limit the waiting to 5 seconds in reopen
> in
> the end too (the same as we do for new open in tty_init_dev).
>
> Dmitry, could you add the limit and handle the return value of
> tty_ldisc_lock now?

Yeah, will do.

--
Thanks,
Dmitry

2018-09-10 05:17:17

by Sergey Senozhatsky

[permalink] [raw]
Subject: Re: [LKP] [tty] 0b4f83d510: INFO:task_blocked_for_more_than#seconds

On (09/07/18 08:39), Jiri Slaby wrote:
> > [ 244.944070]
> > [ 244.944070] Showing all locks held in the system:
> > [ 244.945558] 1 lock held by khungtaskd/18:
> > [ 244.946495] #0: (____ptrval____) (rcu_read_lock){....}, at: debug_show_all_locks+0x16/0x190
> > [ 244.948503] 2 locks held by askfirst/235:
> > [ 244.949439] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
> > [ 244.951762] #1: (____ptrval____) (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x13d/0xa00
>
> Here, it just seems to wait for input from the user.
>
> > [ 244.953799] 1 lock held by validate_data/655:
> > [ 244.954814] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
> > [ 244.956764] 1 lock held by dnsmasq/668:
> > [ 244.957649] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
> > [ 244.959598] 1 lock held by dropbear/734:
> > [ 244.967564] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at: tty_ldisc_ref_wait+0x25/0x50
>
> Hmm, I assume there is another task waiting for write_ldsem and that one
> prevents these readers to proceed. Unfortunately, due to the defunct
> __ptrval__ pointer hashing crap, we do not see who is waiting for what.
> But I am guessing all are the same locks.

Hmm, interesting. Am I getting it right that the test did pass before.
And now we see that sort of/smells like live-lock right after the
introduction of tty_ldisc_lock() to tty_reopen().

> So I think, we are forced to limit the waiting to 5 seconds in reopen in
> the end too (the same as we do for new open in tty_init_dev).

If I got it right, LKP did test the 5*HZ patch

retval = tty_ldisc_lock(tty, 5 * HZ);

At least it's
In-Reply-To: <[email protected]>

and
Message-Id: <[email protected]>

is the patch which does the 5*HZ lock timeout thing.

-ss

2018-09-10 18:51:08

by Dmitry Safonov

[permalink] [raw]
Subject: Re: [LKP] [tty] 0b4f83d510: INFO:task_blocked_for_more_than#seconds

Hi Sergey, Jiri,

On Mon, 2018-09-10 at 14:14 +0900, Sergey Senozhatsky wrote:
> On (09/07/18 08:39), Jiri Slaby wrote:
> > > [ 244.944070]
> > > [ 244.944070] Showing all locks held in the system:
> > > [ 244.945558] 1 lock held by khungtaskd/18:
> > > [ 244.946495] #0: (____ptrval____) (rcu_read_lock){....}, at:
> > > debug_show_all_locks+0x16/0x190
> > > [ 244.948503] 2 locks held by askfirst/235:
> > > [ 244.949439] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at:
> > > tty_ldisc_ref_wait+0x25/0x50
> > > [ 244.951762] #1: (____ptrval____) (&ldata-
> > > >atomic_read_lock){+.+.}, at: n_tty_read+0x13d/0xa00
> >
> > Here, it just seems to wait for input from the user.
> >
> > > [ 244.953799] 1 lock held by validate_data/655:
> > > [ 244.954814] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at:
> > > tty_ldisc_ref_wait+0x25/0x50
> > > [ 244.956764] 1 lock held by dnsmasq/668:
> > > [ 244.957649] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at:
> > > tty_ldisc_ref_wait+0x25/0x50
> > > [ 244.959598] 1 lock held by dropbear/734:
> > > [ 244.967564] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at:
> > > tty_ldisc_ref_wait+0x25/0x50
> >
> > Hmm, I assume there is another task waiting for write_ldsem and
> > that one
> > prevents these readers to proceed. Unfortunately, due to the
> > defunct
> > __ptrval__ pointer hashing crap, we do not see who is waiting for
> > what.
> > But I am guessing all are the same locks.
>
> Hmm, interesting. Am I getting it right that the test did pass
> before.
> And now we see that sort of/smells like live-lock right after the
> introduction of tty_ldisc_lock() to tty_reopen().
>
> > So I think, we are forced to limit the waiting to 5 seconds in
> > reopen in
> > the end too (the same as we do for new open in tty_init_dev).
>
> If I got it right, LKP did test the 5*HZ patch
>
> retval = tty_ldisc_lock(tty, 5 * HZ);
>
> At least it's
> In-Reply-To: <[email protected]>
>
> and
> Message-Id: <[email protected]>
>
> is the patch which does the 5*HZ lock timeout thing.

Yeah, I also noticed on the weekend that the commit in the mentioned
branch is from v1..

Currently, I tried to reproduce it like ~15-20 times, but unlucky :(

It looks like, the lockup wasn't introduced by this commit, but
unfortunately the commit made it more likely. At least, that's what I
suppose after I've found this report:
https://lkml.org/lkml/2017/11/21/216

It seems to me that the lockup is triggered by:
[ 244.948503] 2 locks held by askfirst/235:
[ 244.949439] #0: (____ptrval____) (&tty->ldisc_sem){++++}, at:
tty_ldisc_ref_wait+0x25/0x50
[ 244.951762] #1: (____ptrval____) (&ldata->atomic_read_lock){+.+.},
at: n_tty_read+0x13d/0xa00

Looking into this..

--
Thanks,
Dmitry