Bug 30567

Summary: kqueue/kevent doesn't always work properly with pipes
Product: Base System Reporter: Martin Baker <martinb-fbsd>
Component: kernAssignee: freebsd-bugs (Nobody) <bugs>
Status: Closed FIXED    
Severity: Affects Only Me    
Priority: Normal    
Version: Unspecified   
Hardware: Any   
OS: Any   

Description Martin Baker 2001-09-14 03:50:00 UTC
Using kevent() to read from fds from popen() does not always work; sometimes
kevent() waits the full timeout period and then returns zero events,
even when the pipe is clearly full (as in the output of a small, fast
Unix utility such as "df"). Oddly, printing any debug output

Fix: 

None known, except printing a lot. Creating files also seems to ward
off the bug.
How-To-Repeat: The source for a simple test case follows. Using an fd from popen() and
repeating adding a filter using EV_ONESHOT and then asking for events,
the first, third, and following times I get proper behaviour. The second
time kevent waits the entire timeout period, then returns zero events.

Compiling this program "pipe_kqueue.c" with "make pipe_kqueue", and then
running it, you will see:

0th kevent call started at time offset 0, returned 1
1th kevent call started at time offset 0, returned 0
2th kevent call started at time offset 3, returned 1
3th kevent call started at time offset 3, returned 1
4th kevent call started at time offset 3, returned 1
    All calls completed by time offset 3

If you uncomment the call to print_kevent(), the problem will not occur
(everything happens at time zero, returning one event).

Source code for pipe_kqueue.c (spacing doesn't matter):

/* minimal C example of pipe/kqueue bug */

#include <errno.h>
#include <stdio.h>


#include <sys/time.h>
#include <sys/types.h>
#include <sys/event.h>


static void
print_kevent (struct kevent *e)
{
  fprintf (stderr, "<kevent id=%d fflags=%d data=%d udata=0x%x>\n",
	   e->ident, e->fflags, (unsigned int)e->data,
	   (unsigned int)e->udata);
}


static void
hit_bug ()
{
  FILE *fp;
  int kq, fd;
  int i, retval;
  int count = 0;
  struct kevent event;
  char buf[256];  
  time_t times[20];
  int values[20];
  int entered;

  errno = 0;

  fp = popen ("df -m", "r");
  if (fp == NULL) {
    fprintf (stderr, "Could not open pipe: %s.\n", strerror (errno));
    exit (1);
  }

  kq = kqueue();
  if (kq < 0) {
    fprintf (stderr, "Could not create kqueue: %s.\n", strerror (errno));
    exit (1);
  }

  fd = fileno (fp);
  if (fd < 0) {
    fprintf (stderr, "Could not get fd: %s.\n", strerror (errno));
    exit (1);
  }

  while (1) {
    struct timespec timeout;

    entered = 0;  /* within the while loop because we use EV_ONESHOT */

    timeout.tv_sec = 3;
    timeout.tv_nsec = 0;

    event.ident = fd;
    event.filter = EVFILT_READ;
    event.flags = EV_ONESHOT | EV_ADD;
    event.fflags = 0;
    event.data = 0;
    event.udata = (void *) 0xdeadbeef;


    if (!entered) {
      retval = kevent (kq, &event, 1, NULL, 0, NULL);
      if (retval < 0) {
	fprintf (stderr, "kevent returned %d: %s.\n", retval, strerror (errno));
	exit (1);
      }
      entered = 1;
    }

    times[count] = time (NULL);
    retval = kevent (kq, NULL, 0, &event, 1, &timeout);
    if (retval < 0) {
      fprintf (stderr, "kevent returned %d: %s.\n", retval, strerror (errno));
      exit (1);
    }
    values[count++] = retval;

    if (retval > 0) {
      /* Printing anything out here will hide the bug. */
      /* print_kevent (&event); */
      entered = 1;
    }
    if ((retval == 0) && (count < 15)) continue;

    retval = fread (buf, 50, 1, fp);
    if (retval < 0) {
      fprintf (stderr, "kevent returned %d: %s.\n", retval, strerror (errno));
      exit (1);
    }
    if (retval == 0) break;
  }
  times[count] = time (NULL);
  values[count++] = 0;

  for (i=0; i<count-1; i++) {
    fprintf (stderr,
	     "%dth kevent call started at time offset %d, returned %d\n",
	     i, times[i] - times[0], values[i]);
  }
  fprintf (stderr, "    All calls completed by time offset %d\n",
	   times[count-1] - times[0]);
}


int
main (int argc, char *argv[])
{
  hit_bug();
  return 0;
}
Comment 1 Gregory Bond 2001-09-14 04:26:38 UTC
You are almost certainly being bitten by buffered reads inside fread(), which
is why behaviour changes when you write to STDERR. Replace fread() with read()
and see what happens.
Comment 2 Gregory Bond 2001-09-18 02:21:40 UTC
Submitter reports this is indeed a buffering problem.  This PR can be 
closed.
Comment 3 dwmalone freebsd_committer freebsd_triage 2001-09-18 10:19:12 UTC
State Changed
From-To: open->closed

Explained by buffering in stdio.