linux-kernel - Re: regression in ktime.h circa 3.16.0-rc5+ breaks lirc irsend, bad commit 166afb64511

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20150501050225.4c0ac17c@pog.tecnopolis.ca>
Date:	Fri, 1 May 2015 05:02:25 -0500
From:	Trevor Cordes <trevor@...nopolis.ca>
To:	John Stultz <john.stultz@...aro.org>
Cc:	lkml <linux-kernel@...r.kernel.org>,
	Thomas Gleixner <tglx@...utronix.de>,
	Josh Boyer <jwboyer@...hat.com>,
	One Thousand Gnomes <gnomes@...rguk.ukuu.org.uk>
Subject: Re: regression in ktime.h circa 3.16.0-rc5+ breaks lirc irsend, bad
 commit 166afb64511

On 2015-04-30 John Stultz wrote:
> >From your description it does seem like some sort of edge case
> >problem
> w/ the 32bit ktime_divns(), but I don't see it right off, and I agree
> with Alan to do both calculations and print out warn when that
> happens.
> 
> There's also not a ton of users of that function, but ktime_us_delta()
> is used in drivers/media/rc/ir-lirc-codec.c, which makes use of it in
> ir_lirc_transmit_ir().
> 
> We should instrument that to see if its calculating negative deltas.

Thanks for looking at this!  I didn't have the know-how to add the
debug code myself (I was scared this fn might be called a zillion times
in other kernel operations and overload the system with debug logging).

> I'll send you a debug patch to do the above.

Got the patch.  Sorry for the delay (takes hours to compile using
rpmbuild on this old P4 box).

I think I have "success" in terms of useful debug output (relevant
lines only):

May  1 04:41:08 piles lircd: 'lirc' written to protocols file /sys/class/rc/rc0/protocols
May  1 04:41:08 piles lircd-0.9.1a[978]: lircd(default) ready, using /var/run/lirc/lircd
May  1 04:41:11 piles lircd-0.9.1a[978]: accepted new client on /var/run/lirc/lircd
May  1 04:41:11 piles kernel: [   55.265023] JDB: ktime_to_us: -20782699 -> divns 18446744073688768 != old method: -20783
May  1 04:44:00 piles lircd-0.9.1a[978]: removed client
May  1 04:44:00 piles lircd-0.9.1a[978]: caught signal
May  1 04:44:00 piles lircd: 'lirc' written to protocols file /sys/class/rc/rc0/protocols
May  1 04:44:00 piles lircd-0.9.1a[1523]: lircd(default) ready, using /var/run/lirc/lircd
May  1 04:45:03 piles lircd-0.9.1a[1523]: accepted new client on /var/run/lirc/lircd
May  1 04:45:03 piles kernel: [  287.445027] JDB: ktime_to_us: -20599906 -> divns 18446744073688951 != old method: -20600
May  1 04:45:37 piles lircd-0.9.1a[1523]: removed client
May  1 04:45:37 piles lircd-0.9.1a[1523]: caught signal
May  1 04:45:37 piles lircd: 'lirc' written to protocols file /sys/class/rc/rc0/protocols
May  1 04:45:37 piles lircd-0.9.1a[1579]: lircd(default) ready, using /var/run/lirc/lircd
May  1 04:45:40 piles lircd-0.9.1a[1579]: accepted new client on /var/run/lirc/lircd
May  1 04:45:40 piles kernel: [  324.209023] JDB: ktime_to_us: -20443355 -> divns 18446744073689108 != old method: -20444
May  1 04:46:12 piles lircd-0.9.1a[1579]: removed client
May  1 04:46:12 piles lircd-0.9.1a[1579]: caught signal
May  1 04:46:12 piles lircd: 'lirc' written to protocols file /sys/class/rc/rc0/protocols
May  1 04:46:12 piles lircd-0.9.1a[1597]: lircd(default) ready, using /var/run/lirc/lircd
May  1 04:46:12 piles lircd-0.9.1a[1597]: accepted new client on /var/run/lirc/lircd
May  1 04:46:12 piles kernel: [  356.838029] JDB: ktime_to_us: -20157485 -> divns 18446744073689394 != old method: -20158

The last 2-3 or 3 groups of output I could produce on demand by stopping mythbackend and running:
systemctl restart lircd.service ; irsend SEND_ONCE dct700 info

Subsequent irsends don't trigger the bug, since (as I found out a
while ago) by that point lircd is "hung", at least for a long while.
Hey!  Maybe lircd is then hung for 18446744073689394 us or ns :-)
If this result is used as a delay timer, the negative would produce
0 delay, and the + number the "hang".  I calculate that hang is 584
years?  :-)

So it looks like maybe my theory wasn't so wacky: we're dealing
with a caller passing negative numbers (or 32/64 weirdness).  Very
strange as it seems the caller *wants* (or is happy with) negative
numbers!

Let me know if you need any more debugging/patch-tests.  But give
me 4+ hours between rpmbuilds (probably my responses will be 24-hr
later).

Thanks a million!
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/