[PATCH v2] psmouse: mitigate failing-mouse symptoms

[PATCH v2] psmouse: mitigate failing-mouse symptoms

[Jim Hill]

Keep a failing PS/2 mouse usable until it's convenient to replace it.
Filter incoming packets: drop invalid ones and attempt to correct for
dropped bytes.

New parameter 'filter' makes filtering and logging selectable, set to 0
to shut off all effects.

Tested on AMD64, full coverage. No one else has tried this yet.

Signed-off-by: Jim Hill <gjthill@gmail.com>

---

This is a second version, choosier about accepting apparently-valid
start bytes, no redundant test and more concise syslog and changelog
text.

This is my first patch, I hope I got the procedures right, apologies in
advance if I goofed something.

My mouse failed while in XP, but I didn't know it - it seemed it'd need
cleaning soon. On booting into Linux, it was dangerous, wild slews and
random clicks.  The difference was consistent, making it seem the
problem wasn't the mouse.

Jim
---
 drivers/input/mouse/psmouse-base.c |  108 ++++++++++++++++++++++++++++++++++++
 drivers/input/mouse/psmouse.h      |    7 ++
 2 files changed, 115 insertions(+), 0 deletions(-)

diff --git a/drivers/input/mouse/psmouse-base.c b/drivers/input/mouse/psmouse-base.c
index cd9d0c9..f7421ea 100644
--- a/drivers/input/mouse/psmouse-base.c
+++ b/drivers/input/mouse/psmouse-base.c
@@ -69,6 +69,22 @@ static unsigned int psmouse_resync_time;
 module_param_named(resync_time, psmouse_resync_time, uint, 0644);
 MODULE_PARM_DESC(resync_time, "How long can mouse stay idle before forcing resync (in seconds, 0 = never).");
 
+enum {
+	DROP_BAD = 1,
+	SUMMARIZE_ERRORS = 2,
+	LOG_REJECTS = 4,
+	LOG_ALL	 = 8,
+	ATTEMPT_RECOVERY = 16,
+	DROP_CLAMPED = 32,
+	DROP_PACKET = DROP_CLAMPED | DROP_BAD
+};
+static unsigned int psmouse_filter = DROP_BAD | SUMMARIZE_ERRORS |
+						ATTEMPT_RECOVERY | DROP_CLAMPED;
+module_param_named(filter, psmouse_filter, uint, 0644);
+MODULE_PARM_DESC(filter, "1 = drop invalid or hotio packets, +2=summary-log, "
+		"+4=log-rejected, +8=log-all, +16=attempt-recovery, "
+		"+32=drop-clamped.");
+
 PSMOUSE_DEFINE_ATTR(protocol, S_IWUSR | S_IRUGO,
 			NULL,
 			psmouse_attr_show_protocol, psmouse_attr_set_protocol);
@@ -119,6 +135,85 @@ struct psmouse_protocol {
 	int (*init)(struct psmouse *);
 };
 
+static int psmouse_filter_packet(struct psmouse *m)
+{
+	int todo = 0;
+
+	int xoflow = m->packet[0]>>6 & 1;
+	int yoflow = m->packet[0]>>7 & 1;
+
+	if ((m->packet[0] & 0x08) != 0x08)
+		todo |= DROP_BAD + ATTEMPT_RECOVERY;
+	else if ((xoflow | yoflow) && psmouse_filter & DROP_CLAMPED)
+		todo |= DROP_CLAMPED;
+
+	if (todo & DROP_PACKET) {
+		todo |= LOG_REJECTS;
+		if (m->err_log_counter == 0)
+			m->err_log_base = m->last;
+		++m->err_log_counter;
+	}
+
+	if (time_after(m->last, m->interval_base + HZ/m->rate)) {
+		m->interval_pkts = 0;
+		m->interval_base = m->last;
+	}
+	if (m->interval_pkts > m->rate/HZ + 1) {
+		if (m->hotio_log_counter == 0)
+			m->hotio_log_base = m->last;
+		++m->hotio_log_counter;
+		todo |= DROP_BAD;
+	}
+	++m->interval_pkts;
+
+	if ((todo & psmouse_filter & LOG_REJECTS) |
+			(psmouse_filter & LOG_ALL)) {
+		unsigned long long packet = 0;
+		int p;
+		for (p = 0; p < m->pktcnt; ++p)
+			packet = packet<<8 | m->packet[p];
+		printk(KERN_INFO "psmouse.c: packet %0*llx%s\n", p*2, packet,
+				todo & DROP_PACKET ? " bad" : "");
+	}
+
+	if (m->err_log_counter && time_after(m->last, m->err_log_base + HZ) &&
+		psmouse_filter & (SUMMARIZE_ERRORS | LOG_ALL)) {
+		printk(KERN_WARNING "psmouse.c: %s at %s %lu bad packets\n",
+				m->name, m->phys, m->err_log_counter);
+		m->err_log_counter = m->err_log_base = 0;
+	}
+
+	if (m->hotio_log_counter && time_after(m->last, m->hotio_log_base + HZ)
+			&& psmouse_filter & (SUMMARIZE_ERRORS | LOG_ALL)) {
+		printk(KERN_WARNING "psmouse.c: %s at %s %lu excess packets\n",
+				m->name, m->phys, m->hotio_log_counter);
+		m->hotio_log_counter = m->hotio_log_base = 0;
+	}
+
+	/*
+	 * Take a flyer on recovery, works ok on dropped bytes. Work backwards
+	 * from end looking for a byte that could be a valid start-byte with
+	 * the same buttons down and general direction as the last good packet.
+	 */
+	if (todo & psmouse_filter & ATTEMPT_RECOVERY) {
+		int p = m->pktcnt;
+		while (--p) {
+			if (m->packet[p] == m->last_mbstate) {
+				m->pktcnt -= p;
+				memmove(m->packet, m->packet+p, m->pktcnt);
+				return todo; /* <-- */
+			}
+		}
+		todo &= ~ATTEMPT_RECOVERY;
+	}
+
+	if (todo & psmouse_filter & DROP_PACKET)
+		return todo & psmouse_filter;
+	if (!(todo & DROP_PACKET))
+		m->last_mbstate = m->packet[0] & 0x3f;
+	return 0;
+}
+
 /*
  * psmouse_process_byte() analyzes the PS/2 data stream and reports
  * relevant events to the input module once full packet has arrived.
@@ -135,6 +230,13 @@ static psmouse_ret_t psmouse_process_byte(struct psmouse *psmouse)
 /*
  * Full packet accumulated, process it
  */
+	{
+		int check = psmouse_filter_packet(psmouse);
+		if (check & ATTEMPT_RECOVERY)
+			return PSMOUSE_GOOD_DATA;
+		if (check & DROP_PACKET)
+			return PSMOUSE_FULL_PACKET;
+	}
 
 /*
  * Scroll wheel on IntelliMice, scroll buttons on NetMice
@@ -223,6 +325,12 @@ static inline void __psmouse_set_state(struct psmouse *psmouse, enum psmouse_sta
 	psmouse->pktcnt = psmouse->out_of_sync_cnt = 0;
 	psmouse->ps2dev.flags = 0;
 	psmouse->last = jiffies;
+	psmouse->err_log_base = 0;
+	psmouse->interval_base = 0;
+	psmouse->hotio_log_base = 0;
+	psmouse->err_log_counter = 0;
+	psmouse->interval_pkts = 0;
+	psmouse->hotio_log_counter = 0;
 }
 
 
diff --git a/drivers/input/mouse/psmouse.h b/drivers/input/mouse/psmouse.h
index 593e910..fc4a939 100644
--- a/drivers/input/mouse/psmouse.h
+++ b/drivers/input/mouse/psmouse.h
@@ -47,12 +47,19 @@ struct psmouse {
 	unsigned char pktcnt;
 	unsigned char pktsize;
 	unsigned char type;
+	unsigned char last_mbstate;
 	bool ignore_parity;
 	bool acks_disable_command;
 	unsigned int model;
 	unsigned long last;
 	unsigned long out_of_sync_cnt;
 	unsigned long num_resyncs;
+	unsigned long interval_base;
+	unsigned long interval_pkts;
+	unsigned long hotio_log_base;
+	unsigned long hotio_log_counter;
+	unsigned long err_log_base;
+	unsigned long err_log_counter;
 	enum psmouse_state state;
 	char devname[64];
 	char phys[32];
-- 
1.7.2.3

Re: [PATCH v2] psmouse: mitigate failing-mouse symptoms

[Jonathan Nieder]

Hi Jim,

In January, 2011, Jim Hill wrote:

> Keep a failing PS/2 mouse usable until it's convenient to replace it.
> Filter incoming packets: drop invalid ones and attempt to correct for
> dropped bytes.
>
> New parameter 'filter' makes filtering and logging selectable, set to 0
> to shut off all effects.
[...]
> My mouse failed while in XP, but I didn't know it - it seemed it'd need
> cleaning soon. On booting into Linux, it was dangerous, wild slews and
> random clicks.  The difference was consistent, making it seem the
> problem wasn't the mouse.

I think this would be less controversial if the run-time default were
to disable the feature.  Then if lots of people are setting the
parameter and the idea proves itself, the default could change, and in
the meantime, people with broken setups would know about the breakage
and get a chance to look for other problems.

What do you think?

Thanks for your work,
Jonathan

Re: [PATCH v2] psmouse: mitigate failing-mouse symptoms

[Alessandro Rubini]

> I think this would be less controversial if the run-time default were
> to disable the feature.

Yes, that's the common sensible path to new little-tested features.
As you say, it may become enabled by default over time.

Then, I think it would be good to have a specific sub-structure for
this stuff. It would allow this:

  +       psmouse->err_log_base = 0;
  +       psmouse->interval_base = 0;
  +       psmouse->hotio_log_base = 0;
  +       psmouse->err_log_counter = 0;
  +       psmouse->interval_pkts = 0;
  +       psmouse->hotio_log_counter = 0;

to be replaced with a memset. I also think it would make it clearer
what these are:

  +       unsigned long interval_base;
  +       unsigned long interval_pkts;
  +       unsigned long hotio_log_base;
  +       unsigned long hotio_log_counter;
  +       unsigned long err_log_base;
  +       unsigned long err_log_counter;

to the casual reader.

This is only a suggestion, though.

thanks
/alessandro

Re: [PATCH v2] psmouse: mitigate failing-mouse symptoms

[Jim Hill]

On 09/30/2012 11:02 AM, Alessandro Rubini wrote:
>> I think this would be less controversial if the run-time default were
>> to disable the feature.
>
> Yes, that's the common sensible path

Fixed, there's no way I can test it well enough for anything more widespread.

> Then, I think it would be good to have a specific sub-structure for
> this stuff.

I don't care much either way, though I think I'm missing the point of subbing
in a memset -- only reason I can think of is efficiency which doesn't make
sense to me here.  Ask and I'll add one or both.

> I also think it would make it clearer what these are:

I did de-jargonize the names some,  "interval_start" for "base" makes it
clearer which as you say it could use.

I encountered one other person with this problem and he ran it for a long while
and was happy to have it.  I'm appending the latest version, which is a good
bit improved and what I've been running for the last year amended with the name
and default-filter changes above.

But of course I upgraded a month ago to a box with no PS/2 mouse port, so at
this point all I can do is hope someone finds it helpful.  The reorg'd code 
kinda highlights how incomplete it is, there's lots of mouse models out there.

So if it looks good or almost-good to you and there's anything else I can do,
tell me and I'll be glad to do it.

Thanks,
Jim

>From 2681957a610191cb5d7b7f65be11ea2be06df00f Mon Sep 17 00:00:00 2001
From: Jim Hill <gjthill@gmail.com>
Date: Mon, 28 Mar 2011 13:10:36 -0700
Subject: [PATCH]     Input: psmouse - further improve error handling for
 basic protocols

  Keep a failing PS/2 mouse usable until it's convenient to replace it.
  Filter incoming packets: drop invalid ones and attempt to correct for
  dropped bytes.
 
  New parameter 'filter' makes filtering and logging selectable, leave at 0
  to shut off all effects, 3 to work silently.
--
 drivers/input/mouse/psmouse-base.c | 197 +++++++++++++++++++++++++++++++++++++
 drivers/input/mouse/psmouse.h      |   7 ++
 2 files changed, 204 insertions(+)

diff --git a/drivers/input/mouse/psmouse-base.c b/drivers/input/mous/psmouse-base.c
index 22fe254..4a3a95f 100644
--- a/drivers/input/mouse/psmouse-base.c
+++ b/drivers/input/mouse/psmouse-base.c
@@ -72,6 +72,25 @@ static unsigned int psmouse_resync_time;
 module_param_named(resync_time, psmouse_resync_time, uint, 0644);
 MODULE_PARM_DESC(resync_time, "How long can mouse stay idle before forcing resync (in seconds, 0 = never).");

+enum {
+	DROP_BAD_PACKET = 1,
+	ATTEMPT_SYNC = 2,
+	LOG_SUMMARIES = 4,
+	LOG_MALFORMED = 8,
+	LOG_ALL	 = 16,
+	REPORT_SYNC_FAILURE = 32,
+
+	DEFAULT_FILTER = 0
+};
+static int psmouse_filter = DEFAULT_FILTER;
+module_param_named(filter, psmouse_filter, int, 0644);
+MODULE_PARM_DESC(filter, "1 = drop invalid or hotio packets"
+		", +2 = attempt-sync"
+		", +4 = summary logs"
+		", +8 = log-malformed"
+		",+16 = log-all"
+		",+32 = use hard resets");
+
 PSMOUSE_DEFINE_ATTR(protocol, S_IWUSR | S_IRUGO,
 			NULL,
 			psmouse_attr_show_protocol, psmouse_attr_set_protocol);
@@ -123,6 +142,169 @@ struct psmouse_protocol {
 };

 /*
+ * psmouse_filter_*: diagnose bad data, recover what we can, drop the rest, log
+ * selected events. See input_report_*()s in psmouse_process_byte below, and
+ * <http://www.computer-engineering.org/ps2mouse/>
+ */
+
+static int psmouse_filter_header_byte(enum psmouse_type type, int byte)
+{
+	int todo = 0;
+	if ((byte & 0xc0) &&
+			type != PSMOUSE_THINKPS &&
+			type != PSMOUSE_GENPS)
+		todo |= DROP_BAD_PACKET+ATTEMPT_SYNC;
+	if ((byte & 0x08) == 0 &&
+			type != PSMOUSE_THINKPS &&
+			type != PSMOUSE_CORTRON)
+		todo |= DROP_BAD_PACKET+ATTEMPT_SYNC;
+	return todo;
+}
+
+static int psmouse_filter_wheel_byte(enum psmouse_type type, int byte)
+{
+	int todo = 0;
+	if (type == PSMOUSE_IMPS || type == PSMOUSE_GENPS)
+		if (abs(byte) > 3)
+			todo = DROP_BAD_PACKET+ATTEMPT_SYNC;
+	if (type == PSMOUSE_IMEX)
+		if (((byte&0xC0) == 0) || ((byte&0XC0) == 0xC0))
+			if (abs((byte&0x08)-(byte&0x07)) > 3)
+				todo = DROP_BAD_PACKET+ATTEMPT_SYNC;
+	return todo;
+}
+
+static int psmouse_filter_motion(struct psmouse *m)
+{	/*
+	 * Hunt for implausible accelerations here if it ever seems necessary.
+	 * Header/wheel sniffing seems to detect everything recoverable so far.
+	 */
+	return 0;
+}
+
+static int psmouse_filter_hotio(struct psmouse *m)
+{
+	int ret = 0;
+	if (time_after(m->last, m->hotio_interval_start + HZ/m->rate)) {
+		m->hotio_interval_pkts = 0;
+		m->hotio_interval_start = m->last;
+	}
+	if (m->hotio_interval_pkts++ > m->rate/HZ + 1) {
+		if (m->hotio_log_counter == 0)
+			m->hotio_log_interval_start = m->last;
+		++m->hotio_log_counter;
+		ret = DROP_BAD_PACKET;
+	}
+	return ret;
+}
+
+static void psmouse_filter_packet_logger(struct psmouse *m, int todo,
+		const char *tag)
+{
+	if ((todo & psmouse_filter & LOG_MALFORMED) ||
+			(psmouse_filter & LOG_ALL)) {
+		unsigned long long packet = 0;
+		int p;
+		for (p = 0; p < m->pktcnt; ++p)
+			packet = packet<<8 | m->packet[p];
+		printk(KERN_INFO "psmouse.c: packet %0*llx%s\n", p*2, packet,
+			tag ? tag : "");
+	}
+}
+
+static int psmouse_filter_inspect_packet(struct psmouse *m)
+{
+	int todo = 0;
+	todo |= psmouse_filter_header_byte(m->type, m->packet[0]);
+	todo |= psmouse_filter_motion(m);
+	todo |= psmouse_filter_wheel_byte(m->type, (signed char)m->packet[3]);
+	if (todo & DROP_BAD_PACKET) {
+		todo |= LOG_MALFORMED;
+		if (m->err_log_counter == 0)
+			m->err_log_interval_start = m->last;
+		++m->err_log_counter;
+	}
+	return todo;
+}
+
+/*
+ * find-sync: if the mouse dropped one or more bytes the next packet start
+ * byte's almost certainly in this buffer. Return its offset if we can find it.
+ */
+static unsigned psmouse_filter_find_sync(struct psmouse *m)
+{
+	int p;
+
+	/* same buttons, same general direction as last report? Seems best */
+	for (p = m->pktcnt; --p ; )
+		if (m->packet[p] == m->last_good_packet[0])
+			return p;
+
+	/* same or no buttons, plausible direction from what we can see? */
+	for (p = m->pktcnt; --p ; ) {
+		signed char test0 = (signed char)m->packet[p];
+		signed char last0 = (signed char)m->last_good_packet[0];
+		signed char test1 = (signed char)m->packet[(p+1)%m->pktcnt];
+		signed char test2 = (signed char)m->packet[(p+2)%m->pktcnt];
+		if (((test0&7) == 0 || (test0&7) == (last0&7)) &&
+				(test0>>4&1) == (test1>>7&1) &&
+				(test0>>5&1) == (test2>>7&1) &&
+				!psmouse_filter_header_byte(m->type, test0))
+			return p;
+	}
+	/* nothing looks good */
+	return 0;
+}
+
+static void psmouse_filter_write_summary_logs(struct psmouse *m)
+{
+	if (m->err_log_counter && time_after(m->last, m->err_log_interval_start+HZ)) {
+		printk(KERN_WARNING "psmouse.c: %s at %s %lu bad packets\n",
+				m->name, m->phys, m->err_log_counter);
+		m->err_log_counter = m->err_log_interval_start = 0;
+	}
+	if (m->hotio_log_counter && time_after(m->last, m->hotio_log_interval_start+HZ)) {
+		printk(KERN_WARNING "psmouse.c: %s at %s %lu excess packets\n",
+				m->name, m->phys, m->hotio_log_counter);
+		m->hotio_log_counter = m->hotio_log_interval_start = 0;
+	}
+}
+
+static int psmouse_filter_packet(struct psmouse *m)
+{
+	int todo;
+
+	if (psmouse_filter < 0)
+		psmouse_filter = DEFAULT_FILTER;
+
+	todo = psmouse_filter_inspect_packet(m);
+
+	if (!(todo & DROP_BAD_PACKET))
+		todo |= psmouse_filter_hotio(m);
+
+	psmouse_filter_packet_logger(m, todo, todo&LOG_MALFORMED ? " bad" : 0);
+	if (psmouse_filter & (LOG_SUMMARIES | LOG_ALL))
+		psmouse_filter_write_summary_logs(m);
+
+	if (todo & psmouse_filter & ATTEMPT_SYNC) {
+		unsigned p = psmouse_filter_find_sync(m);
+		if (p) {
+			m->pktcnt -= p;
+			memmove(m->packet, m->packet+p, m->pktcnt);
+			psmouse_filter_packet_logger(m, todo, " sync");
+		} else {
+			todo |= REPORT_SYNC_FAILURE;
+			todo &= ~ATTEMPT_SYNC;
+		}
+	}
+
+	if (!(todo & DROP_BAD_PACKET))
+		memcpy(m->last_good_packet, m->packet, sizeof m->packet);
+
+	return todo & psmouse_filter;
+}
+
+/*
  * psmouse_process_byte() analyzes the PS/2 data stream and reports
  * relevant events to the input module once full packet has arrived.
  */
@@ -135,6 +317,15 @@ psmouse_ret_t psmouse_process_byte(struct psmouse *psmouse)
 	if (psmouse->pktcnt < psmouse->pktsize)
 		return PSMOUSE_GOOD_DATA;

+	{
+		int filter = psmouse_filter_packet(psmouse);
+		if (filter & ATTEMPT_SYNC)
+			return PSMOUSE_GOOD_DATA;
+		if (filter & REPORT_SYNC_FAILURE)
+			return PSMOUSE_BAD_DATA;
+		if (filter & DROP_BAD_PACKET)
+			return PSMOUSE_FULL_PACKET;
+	}
 /*
  * Full packet accumulated, process it
  */
@@ -226,6 +417,12 @@ static inline void __psmouse_set_state(struct psmouse *psmouse, enum psmouse_sta
 	psmouse->pktcnt = psmouse->out_of_sync_cnt = 0;
 	psmouse->ps2dev.flags = 0;
 	psmouse->last = jiffies;
+	psmouse->err_log_interval_start = 0;
+	psmouse->err_log_counter = 0;
+	psmouse->hotio_interval_start = 0;
+	psmouse->hotio_interval_pkts = 0;
+	psmouse->hotio_log_interval_start = 0;
+	psmouse->hotio_log_counter = 0;
 }


diff --git a/drivers/input/mouse/psmouse.h b/drivers/input/mouse/psmouse.h
index fe1df23..7d8817e7 100644
--- a/drivers/input/mouse/psmouse.h
+++ b/drivers/input/mouse/psmouse.h
@@ -44,6 +44,7 @@ struct psmouse {
 	char *vendor;
 	char *name;
 	unsigned char packet[8];
+	unsigned char last_good_packet[8];
 	unsigned char badbyte;
 	unsigned char pktcnt;
 	unsigned char pktsize;
@@ -54,6 +55,12 @@ struct psmouse {
 	unsigned long last;
 	unsigned long out_of_sync_cnt;
 	unsigned long num_resyncs;
+	unsigned long hotio_interval_start;
+	unsigned long hotio_interval_pkts;
+	unsigned long hotio_log_interval_start;
+	unsigned long hotio_log_counter;
+	unsigned long err_log_interval_start;
+	unsigned long err_log_counter;
 	enum psmouse_state state;
 	char devname[64];
 	char phys[32];
-- 
1.7.11.rc2.220.g2b5a256