Re: Strange intermittent EIO error when writing to stdout since v3.8.0

[Peter Hurley <peter@hurleysoftware.com>]

On 06/13/2013 06:39 AM, Markus Trippelsdorf wrote:
> On 2013.06.07 at 20:22 +0200, Mikael Pettersson wrote:
>> Peter Hurley writes:
>>   > Based on the other reports from Mikael and David, I suspect this problem
>>   > may have to do with my commit 699390354da6c258b65bf8fa79cfd5feaede50b6:
>>   >
>>   >    pty: Ignore slave pty close() if never successfully opened
>>   >
>>   > This commit poisons the pty under certain error conditions that may
>>   > occur from parallel open()s (or parallel close() with pending write()).
>>   >
>>   > It's unclear to me which error condition is triggered and how user-space
>>   > got an open file descriptor but that seems the most likely. Is the problem
>>   > reproducible enough that a debug patch would likely trigger?
>>
>> In my case the problem occurred frequently enough that I've been forced
>> to change my build procedures to avoid it.  I'd welcome a debug patch.
>
> Since apparently no debugging patch is forthcoming, maybe it's time to
> test the simple revert of commit 699390354da.

I apologize for the delay.

Here's a debug patch which I hope will narrow down the circumstances of
this error condition.

Regards,
Peter Hurley

PS - Don't get excited about EIO from read() which you will see during
boot. That's expected when the slave closes and the master is parked on
a blocking read().

--- >% ---
Subject: [PATCH] tty: Debug EIO from write()


Signed-off-by: Peter Hurley <peter@hurleysoftware.com>
---
  drivers/tty/pty.c    | 22 +++++++++++++++++++---
  drivers/tty/tty_io.c | 51 ++++++++++++++++++++++++++++++++++++++++++---------
  2 files changed, 61 insertions(+), 12 deletions(-)

diff --git a/drivers/tty/pty.c b/drivers/tty/pty.c
index 9c2f1bc..2ce2bb2 100644
--- a/drivers/tty/pty.c
+++ b/drivers/tty/pty.c
@@ -25,6 +25,16 @@
  #include <linux/slab.h>
  #include <linux/mutex.h>

+#define TTY_DEBUG_EIO 1
+
+#ifdef TTY_DEBUG_EIO
+#define tty_debug_eio(tty, f, args...) ({                       \
+    char __b[64];                                   \
+    printk(KERN_DEBUG "%s: %s: " f, __func__, tty_name(tty, __b), ##args); \
+})
+#else
+#define tty_debug_eio(tty, f, args...)
+#endif

  #ifdef CONFIG_UNIX98_PTYS
  static struct tty_driver *ptm_driver;
@@ -246,12 +256,18 @@ static int pty_open(struct tty_struct *tty, struct file *filp)
      set_bit(TTY_IO_ERROR, &tty->flags);

      retval = -EIO;
-    if (test_bit(TTY_OTHER_CLOSED, &tty->flags))
+    if (test_bit(TTY_OTHER_CLOSED, &tty->flags)) {
+        tty_debug_eio(tty, "other pty closed (%#lx)\n", tty->flags);
          goto out;
-    if (test_bit(TTY_PTY_LOCK, &tty->link->flags))
+    }
+    if (test_bit(TTY_PTY_LOCK, &tty->link->flags)) {
+        tty_debug_eio(tty, "ptm still locked\n");
          goto out;
-    if (tty->driver->subtype == PTY_TYPE_SLAVE && tty->link->count != 1)
+    }
+    if (tty->driver->subtype == PTY_TYPE_SLAVE && tty->link->count != 1) {
+        tty_debug_eio(tty, "ptm open count (%d)\n", tty->link->count);
          goto out;
+    }

      clear_bit(TTY_IO_ERROR, &tty->flags);
      clear_bit(TTY_OTHER_CLOSED, &tty->link->flags);
diff --git a/drivers/tty/tty_io.c b/drivers/tty/tty_io.c
index 62e942d..e71c61f 100644
--- a/drivers/tty/tty_io.c
+++ b/drivers/tty/tty_io.c
@@ -105,11 +105,21 @@
  #include <linux/kmod.h>
  #include <linux/nsproxy.h>

-#undef TTY_DEBUG_HANGUP
+#define TTY_DEBUG_HANGUP 1
+#define TTY_DEBUG_EIO 1

  #define TTY_PARANOIA_CHECK 1
  #define CHECK_TTY_COUNT 1

+#ifdef TTY_DEBUG_EIO
+#define tty_debug_eio(tty, f, args...) ({                       \
+    char __b[64];                                   \
+    printk(KERN_DEBUG "%s: %s: " f, __func__, tty_name(tty, __b), ##args); \
+})
+#else
+#define tty_debug_eio(tty, f, args...)
+#endif
+
  struct ktermios tty_std_termios = {    /* for the benefit of tty drivers  */
      .c_iflag = ICRNL | IXON,
      .c_oflag = OPOST | ONLCR,
@@ -424,6 +434,7 @@ int tty_check_change(struct tty_struct *tty)
      if (is_ignored(SIGTTOU))
          goto out;
      if (is_current_pgrp_orphaned()) {
+        tty_debug_eio(tty, "pgrp orphaned?? (%#lx)\n", tty->flags);
          ret = -EIO;
          goto out;
      }
@@ -448,6 +459,9 @@ static ssize_t hung_up_tty_read(struct file *file, char __user *buf,
  static ssize_t hung_up_tty_write(struct file *file, const char __user *buf,
                   size_t count, loff_t *ppos)
  {
+    struct tty_struct *tty = file_tty(file);
+
+    tty_debug_eio(tty, "%#lx\n", tty ? tty->flags : -1L);
      return -EIO;
  }

@@ -1020,16 +1034,22 @@ static ssize_t tty_read(struct file *file, char __user *buf, size_t count,

      if (tty_paranoia_check(tty, inode, "tty_read"))
          return -EIO;
-    if (!tty || (test_bit(TTY_IO_ERROR, &tty->flags)))
+    if (!tty || (test_bit(TTY_IO_ERROR, &tty->flags))) {
+        tty_debug_eio(tty, "%#lx\n", tty ? tty->flags : -1L);
          return -EIO;
+    }

      /* We want to wait for the line discipline to sort out in this
         situation */
      ld = tty_ldisc_ref_wait(tty);
-    if (ld->ops->read)
+    if (ld->ops->read) {
          i = (ld->ops->read)(tty, file, buf, count);
-    else
+        if (i == -EIO)
+            tty_debug_eio(tty, "ldisc error (%#lx)\n", tty->flags);
+    } else {
+        tty_debug_eio(tty, "no ldisc read method???\n");
          i = -EIO;
+    }
      tty_ldisc_deref(ld);

      if (i > 0)
@@ -1197,18 +1217,31 @@ static ssize_t tty_write(struct file *file, const char __user *buf,

      if (tty_paranoia_check(tty, file_inode(file), "tty_write"))
          return -EIO;
-    if (!tty || !tty->ops->write ||
-        (test_bit(TTY_IO_ERROR, &tty->flags)))
-            return -EIO;
+    if (!tty || !tty->ops->write || (test_bit(TTY_IO_ERROR, &tty->flags))) {
+        if (tty && !tty->ops->write)
+            tty_debug_eio(tty, "no driver write method???\n");
+        else
+            tty_debug_eio(tty, "%#lx\n", tty ? tty->flags : -1L);
+        return -EIO;
+    }
      /* Short term debug to catch buggy drivers */
      if (tty->ops->write_room == NULL)
          printk(KERN_ERR "tty driver %s lacks a write_room method.\n",
              tty->driver->name);
      ld = tty_ldisc_ref_wait(tty);
-    if (!ld->ops->write)
+    if (!ld->ops->write) {
+        tty_debug_eio(tty, "no ldisc write method???\n");
          ret = -EIO;
-    else
+    } else {
          ret = do_tty_write(ld->ops->write, tty, file, buf, count);
+        if (ret == -EIO) {
+            if (tty_hung_up_p(file))
+                tty_debug_eio(tty, "hung up\n");
+            else
+                tty_debug_eio(tty, "ldisc error: flags=%#lx count=%d other=%d\n",
+                          tty->flags, tty->count, tty->link ? tty->link->count : -1);
+        }
+    }
      tty_ldisc_deref(ld);
      return ret;
  }
-- 
1.8.1.2