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 dja@axtens.net Cc: Dmitry Vyukov dvyukov@google.com Cc: Michael Neuling mikey@neuling.org Cc: Mikulas Patocka mpatocka@redhat.com Cc: Pasi Kärkkäinen pasik@iki.fi Cc: Peter Hurley peter@hurleysoftware.com Cc: Sergey Senozhatsky sergey.senozhatsky.work@gmail.com Cc: Tan Xiaojun tanxiaojun@huawei.com (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(-)
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 gregkh@linuxfoundation.org Cc: Jiri Slaby jslaby@suse.com Cc: stable@vger.kernel.org Signed-off-by: Dmitry Safonov dima@arista.com --- 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; }
/**
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 gregkh@linuxfoundation.org Cc: Jiri Slaby jslaby@suse.com Cc: stable@vger.kernel.org Signed-off-by: Dmitry Safonov dima@arista.com
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,
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 gregkh@linuxfoundation.org Cc: Jiri Slaby jslaby@suse.com Cc: stable@vger.kernel.org Signed-off-by: Dmitry Safonov dima@arista.com
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..
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,
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.
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 gregkh@linuxfoundation.org Cc: Jiri Slaby jslaby@suse.com Cc: stable@vger.kernel.org Signed-off-by: Dmitry Safonov dima@arista.com --- 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; }
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
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.
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
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 gregkh@linuxfoundation.org Cc: Jiri Slaby jslaby@suse.com Cc: stable@vger.kernel.org Signed-off-by: Dmitry Safonov dima@arista.com
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,
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,
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 gregkh@linuxfoundation.org Cc: Jiri Slaby jslaby@suse.com Cc: stable@vger.kernel.org Signed-off-by: Dmitry Safonov dima@arista.com
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;
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=f08670354701fa64cc0dd3c0128a491bdb16adc... .
syzbot is now testing a patch from Jiri Slaby.
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=f08670354701fa64cc0dd3c0128a491bdb16adc... .
syzbot is now testing a patch from Jiri Slaby.
Yes, my patch passed, so could you add: Reported-by: syzbot+3aa9784721dfb90e984d@syzkaller.appspotmail.com
(not adding tested-by as this particular patch was not tested, but shoiuld work the same way.)
thanks,
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=f08670354701fa64cc0dd3c0128a491bdb16adc... .
syzbot is now testing a patch from Jiri Slaby.
Yes, my patch passed, so could you add: Reported-by: syzbot+3aa9784721dfb90e984d@syzkaller.appspotmail.com
(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.
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...
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.
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... 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
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... 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,
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.
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: 20180829022353.23568-3-dima@arista.com
and Message-Id: 20180829022353.23568-3-dima@arista.com
is the patch which does the 5*HZ lock timeout thing.
-ss
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: 20180829022353.23568-3-dima@arista.com
and Message-Id: 20180829022353.23568-3-dima@arista.com
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..
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...
CentOS bug: https://bugs.centos.org/view.php?id=13713
Thanks,
-- Pasi
Cc: Daniel Axtens dja@axtens.net Cc: Dmitry Vyukov dvyukov@google.com Cc: Michael Neuling mikey@neuling.org Cc: Mikulas Patocka mpatocka@redhat.com Cc: Pasi Kärkkäinen pasik@iki.fi Cc: Peter Hurley peter@hurleysoftware.com Cc: Sergey Senozhatsky sergey.senozhatsky.work@gmail.com Cc: Tan Xiaojun tanxiaojun@huawei.com (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
linux-stable-mirror@lists.linaro.org
-
Benjamin Herrenschmidt -
Dmitry Safonov -
Jiri Slaby -
Jiri Slaby -
kernel test robot -
Pasi Kärkkäinen -
Sergey Senozhatsky -
Tetsuo Handa -
Tetsuo Handa