[PATCH libevdev 3/3] Warn about a SYN_DROPPED right after finishing a sync

[Peter Hutterer]

On Fri, Jan 17, 2014 at 01:25:11PM +0100, David Herrmann wrote:
> Hi
> 
> On Fri, Jan 17, 2014 at 4:31 AM, Peter Hutterer
> <peter.hutterer at who-t.net> wrote:
> > If the first event after a completed device sync is a SYN_DROPPED, warn the
> > user that they're not fast enough handling this device.
> >
> > The test for this is rather complicated since we can't write SYN_DROPPED
> > through uinput so we have to juggle the device fd and a pipe and switch
> > between the two at the right time (taking into account that libevdev will read
> > events from the fd whenever it can).
> >
> > Signed-off-by: Peter Hutterer <peter.hutterer at who-t.net>
> > ---
> >  libevdev/libevdev.c         |  11 +++--
> >  test/test-libevdev-events.c | 110 ++++++++++++++++++++++++++++++++++++++++++++
> >  2 files changed, 118 insertions(+), 3 deletions(-)
> >
> > diff --git a/libevdev/libevdev.c b/libevdev/libevdev.c
> > index 59625a4..cf532e3 100644
> > --- a/libevdev/libevdev.c
> > +++ b/libevdev/libevdev.c
> > @@ -816,8 +816,6 @@ libevdev_next_event(struct libevdev *dev, unsigned int flags, struct input_event
> >                 dev->sync_state = SYNC_NONE;
> >         }
> >
> > -       /* FIXME: if the first event after SYNC_IN_PROGRESS is a SYN_DROPPED, log this */
> > -
> >         /* Always read in some more events. Best case this smoothes over a potential SYN_DROPPED,
> >            worst case we don't read fast enough and end up with SYN_DROPPED anyway.
> >
> > @@ -856,8 +854,15 @@ libevdev_next_event(struct libevdev *dev, unsigned int flags, struct input_event
> >         if (flags & LIBEVDEV_READ_FLAG_SYNC && dev->queue_nsync > 0) {
> >                 dev->queue_nsync--;
> >                 rc = LIBEVDEV_READ_STATUS_SYNC;
> > -               if (dev->queue_nsync == 0)
> > +               if (dev->queue_nsync == 0) {
> > +                       struct input_event next;
> >                         dev->sync_state = SYNC_NONE;
> > +
> > +                       if (queue_peek(dev, 0, &next) == 0 &&
> > +                           next.type == EV_SYN && next.code == SYN_DROPPED)
> > +                               log_info("SYN_DROPPED received after finished "
> > +                                        "sync - you're not keeping up\n");
> > +               }
> 
> Maybe we want something like printk_ratelimit() here. logging in a
> fast-path is always ugly.. Anyhow, log_warn() seems more appropriate.

yeah, changing to log_warn is ok.  I'll look into rate-limiting this but I
don't think that's an issue.

as for the logging in a fast-path: yeah, but this message is explicitely
there when the fast path isn't as fast as it should be ;)

> Furthermore, if queue_peek() returns non-0, we don't have a next-event
> but don't warn on the next iteration when we read the event (as we
> already set sync_state = SYNC_NONE). But I guess that's fine as we
> always read as much as we can so in this case the queue was empty and
> the next event cannot be a SYN_DROPPED then (or at least we wouldn't
> care).

correct, I don't think that's an issue, or at least a corner-case enough
that we shouldn't worry about it. it would require the caller to be fast
enough for all the syn events but the last EV_SYN, then pause before
reading that to trigger a kernel SYN_DROPPED. since the caller doesn't know
how many events are in the sync queue and thus doesn't know when the next
event is the SYN_DROPPED, that's hard to trigger even intentionally, let
alone unintenionally.

> >         }
> >
> >  out:
> > diff --git a/test/test-libevdev-events.c b/test/test-libevdev-events.c
> > index 47bbdb9..65d28fd 100644
> > --- a/test/test-libevdev-events.c
> > +++ b/test/test-libevdev-events.c
> > @@ -25,6 +25,7 @@
> >  #include <errno.h>
> >  #include <unistd.h>
> >  #include <fcntl.h>
> > +#include <stdio.h>
> >
> >  #include "test-common.h"
> >
> > @@ -122,6 +123,114 @@ START_TEST(test_syn_dropped_event)
> >  }
> >  END_TEST
> >
> > +void double_syn_dropped_logfunc(enum libevdev_log_priority priority,
> > +                               void *data,
> > +                               const char *file, int line,
> > +                               const char *func,
> > +                               const char *format, va_list args)
> > +{
> > +       unsigned int *hit = data;
> > +       *hit = 1;
> > +       printf("Expected_error_message:");
> > +       vprintf(format, args);
> 
> Any reason we print this error? We fail if "hit" isn't set and now we
> just clutter the error-log. I always find it quite annoying that the
> test-results print a log of expected errors.

no specific reason, no. for debugging it's easier to see the messages but I
can remove that.

> 
> > +}
> > +
> > +START_TEST(test_double_syn_dropped_event)
> > +{
> > +       struct uinput_device* uidev;
> > +       struct libevdev *dev;
> > +       int rc;
> > +       struct input_event ev;
> > +       int pipefd[2];
> > +       unsigned int logfunc_hit = 0;
> > +
> > +       rc = test_create_device(&uidev, &dev,
> > +                               EV_SYN, SYN_REPORT,
> > +                               EV_SYN, SYN_DROPPED,
> > +                               EV_REL, REL_X,
> > +                               EV_REL, REL_Y,
> > +                               EV_KEY, BTN_LEFT,
> > +                               -1);
> > +       ck_assert_msg(rc == 0, "Failed to create device: %s", strerror(-rc));
> > +
> > +       libevdev_set_log_function(double_syn_dropped_logfunc,  &logfunc_hit);
> > +
> > +       /* This is a bit complicated:
> > +          we can't get SYN_DROPPED through uinput, so we push two events down
> > +          uinput, and fetch one off libevdev (reading in the other one on the
> > +          way). Then write a SYN_DROPPED on a pipe, switch the fd and read
> > +          one event off the wire (but returning the second event from
> > +          before). Switch back, so that when we do read off the SYN_DROPPED
> > +          we have the fd back on the device and the ioctls work.
> > +        */
> 
> lol.. no time to review that right now, but if it works I'm fine with
> it. As long as we don't call any ioctl() on it, it should work just
> fine. I wonder why you didn't try to emulate an evdev device via CUSE
> (character-device in user-space) :p

it'd be easier to fix the kernel to allow SYN_DROPPED
through uinput though.

Cheers,
   Peter