logkeys doesn't log everything sent if keys are sent in fast bursts (by hardware)

[GoogleCodeExporter]

What steps will reproduce the problem?
1. Program a USB device ( a Teensy++2.0 from www.pjrc.com) that emulates a USB 
keyboard, but which doesn't require a human to actually press the keys.
2. Plug in the USB device, and have it send a fast burst of data via the 
keyboard input.
3. The data is not logged by logkeys, but is detected by the active window.

What is the expected output?
All of the data sent via the keyboard input should be captured by logkeys, even 
if it is sent in fast bursts.

What do you see instead?
I see the human entered text before and after where the machine-generated text 
should appear, but not the machine-generated burst of characters

What version of the product are you using (`logkeys --help`)?
0.1.0

On what operating system?
Ubuntu 11.04

Other info:

$ uname -a
Linux asus-eeepc 2.6.38-10-generic #46-Ubuntu SMP Tue Jun 28 15:05:41 UTC 2011 
i686 i686 i386 GNU/Linux

$ /proc/bus/input/devices
I: Bus=0019 Vendor=0000 Product=0005 Version=0000
N: Name="Lid Switch"
P: Phys=PNP0C0D/button/input0
S: Sysfs=/devices/LNXSYSTM:00/device:00/PNP0C0D:00/input/input0
U: Uniq=
H: Handlers=event0 
B: PROP=0
B: EV=21
B: SW=1

I: Bus=0019 Vendor=0000 Product=0003 Version=0000
N: Name="Sleep Button"
P: Phys=PNP0C0E/button/input0
S: Sysfs=/devices/LNXSYSTM:00/device:00/PNP0C0E:00/input/input1
U: Uniq=
H: Handlers=kbd event1 
B: PROP=0
B: EV=3
B: KEY=4000 0 0 0 0

I: Bus=0019 Vendor=0000 Product=0001 Version=0000
N: Name="Power Button"
P: Phys=PNP0C0C/button/input0
S: Sysfs=/devices/LNXSYSTM:00/device:00/PNP0C0C:00/input/input2
U: Uniq=
H: Handlers=kbd event2 
B: PROP=0
B: EV=3
B: KEY=100000 0 0 0

I: Bus=0019 Vendor=0000 Product=0001 Version=0000
N: Name="Power Button"
P: Phys=LNXPWRBN/button/input0
S: Sysfs=/devices/LNXSYSTM:00/LNXPWRBN:00/input/input3
U: Uniq=
H: Handlers=kbd event3 
B: PROP=0
B: EV=3
B: KEY=100000 0 0 0

I: Bus=0011 Vendor=0001 Product=0001 Version=ab41
N: Name="AT Translated Set 2 keyboard"
P: Phys=isa0060/serio0/input0
S: Sysfs=/devices/platform/i8042/serio0/input/input4
U: Uniq=
H: Handlers=sysrq kbd event4 
B: PROP=0
B: EV=120013
B: KEY=4 2000000 3803078 f800d001 feffffdf ffefffff ffffffff fffffffe
B: MSC=10
B: LED=7

I: Bus=0019 Vendor=0000 Product=0006 Version=0000
N: Name="Video Bus"
P: Phys=LNXVIDEO/video/input0
S: Sysfs=/devices/LNXSYSTM:00/device:00/PNP0A08:00/LNXVIDEO:00/input/input5
U: Uniq=
H: Handlers=kbd event5 
B: PROP=0
B: EV=3
B: KEY=3e000b 0 0 0 0 0 0 0

I: Bus=0019 Vendor=0000 Product=0000 Version=0000
N: Name="Asus EeePC extra buttons"
P: Phys=eeepc/input0
S: Sysfs=/devices/platform/eeepc/input/input6
U: Uniq=
H: Handlers=rfkill kbd event6 
B: PROP=0
B: EV=13
B: KEY=100000 0 0 0 21400b 400 1800000 1300000 e0000 0 0 0
B: MSC=10

I: Bus=0011 Vendor=0002 Product=000e Version=0000
N: Name="ETPS/2 Elantech Touchpad"
P: Phys=isa0060/serio1/input0
S: Sysfs=/devices/platform/i8042/serio1/input/input7
U: Uniq=
H: Handlers=mouse0 event7 
B: PROP=0
B: EV=b
B: KEY=e420 0 30000 0 0 0 0 0 0 0 0
B: ABS=f0003

I: Bus=0003 Vendor=04f2 Product=b071 Version=1518
N: Name="CNF7129"
P: Phys=usb-0000:00:1d.7-8/button
S: Sysfs=/devices/pci0000:00/0000:00:1d.7/usb1/1-8/1-8:1.0/input/input8
U: Uniq=
H: Handlers=kbd event8 
B: PROP=0
B: EV=3
B: KEY=100000 0 0 0 0 0 0

I: Bus=0000 Vendor=0000 Product=0000 Version=0000
N: Name="HDA Intel Mic"
P: Phys=ALSA
S: Sysfs=/devices/pci0000:00/0000:00:1b.0/sound/card0/input9
U: Uniq=
H: Handlers=event9 
B: PROP=0
B: EV=21
B: SW=10

I: Bus=0000 Vendor=0000 Product=0000 Version=0000
N: Name="HDA Intel Headphone"
P: Phys=ALSA
S: Sysfs=/devices/pci0000:00/0000:00:1b.0/sound/card0/input10
U: Uniq=
H: Handlers=event10 
B: PROP=0
B: EV=21
B: SW=4

I: Bus=0003 Vendor=1bcf Product=0007 Version=0110
N: Name="USB Optical Mouse"
P: Phys=usb-0000:00:1d.7-3.4/input0
S: Sysfs=/devices/pci0000:00/0000:00:1d.7/usb1/1-3/1-3.4/1-3.4:1.0/input/input11
U: Uniq=
H: Handlers=mouse1 event11 
B: PROP=0
B: EV=1f
B: KEY=70000 0 0 0 0 0 0 0 0
B: REL=143
B: ABS=100 0
B: MSC=10

I: Bus=0003 Vendor=16c0 Product=0482 Version=0111
N: Name="Teensy Keyboard/Mouse/Joystick"
P: Phys=usb-0000:00:1d.7-3.2/input0
S: 
Sysfs=/devices/pci0000:00/0000:00:1d.7/usb1/1-3/1-3.2/1-3.2:1.0/input/input155
U: Uniq=
H: Handlers=sysrq kbd event12 
B: PROP=0
B: EV=120013
B: KEY=800000 0 e0b0ffdf 1cfffff ffffffff fffffffe
B: MSC=10
B: LED=1f

I: Bus=0003 Vendor=16c0 Product=0482 Version=0111
N: Name="Teensy Keyboard/Mouse/Joystick"
P: Phys=usb-0000:00:1d.7-3.2/input1
S: 
Sysfs=/devices/pci0000:00/0000:00:1d.7/usb1/1-3/1-3.2/1-3.2:1.1/input/input156
U: Uniq=
H: Handlers=mouse2 event13 
B: PROP=0
B: EV=17
B: KEY=70000 0 0 0 0 0 0 0 0
B: REL=103
B: MSC=10

I: Bus=0003 Vendor=16c0 Product=0482 Version=0111
N: Name="Teensy Keyboard/Mouse/Joystick"
P: Phys=usb-0000:00:1d.7-3.2/input3
S: 
Sysfs=/devices/pci0000:00/0000:00:1d.7/usb1/1-3/1-3.2/1-3.2:1.3/input/input157
U: Uniq=
H: Handlers=event14 js0 
B: PROP=0
B: EV=1b
B: KEY=ffff0000 0 0 0 0 0 0 0 0 0 0 0 0 ffff 0 0 0 0 0 0 0 0 0
B: ABS=300e7
B: MSC=10

Original issue reported on code.google.com by colm.p.o...@gmail.com on 31 Jul 2011 at 9:58

[GoogleCodeExporter]

Did you try running logkeys with --device=event12 (or event13 or event14 
parameter) switch?
The thing is, logkeys currently only 'listens' on a single interface (by 
default, I think it should be event4, "AT Translated Set 2 keyboard"). If that 
interface is e.g. event4, then logkeys only receives input from your default 
serial keyboard and skips any input from Teensy (event12, event13 or event14).

Original comment by kernc...@gmail.com on 1 Aug 2011 at 11:07

• Changed state: Duplicate

[GoogleCodeExporter]

Sorry. I should have said. I ran it with --device=event12. That's the interface 
that the device is connected to.  It successfully captures keys that come in on 
that same interface if they were initiated by a human (ie, they came in 
slowly), but it completely misses bursts that are sent by the internal logic of 
the device, rather than by a person pressing keys on the keyboard attached to 
the Teensy microcontroller.

I don't think that this is a duplicate issue.

Original comment by colm.p.o...@gmail.com on 1 Aug 2011 at 11:57

[GoogleCodeExporter]

ok, thanks, I understand.

however, in that case I'm clueless as what the culprit might be.
obviously, if logkeys shows no output, it gets no input.
and if it gets no input, then likely kernel produces none on that interface.
(confirm with `sudo cat /dev/input/event12` before bursting; it should be 
silent.)

Original comment by kernc...@gmail.com on 1 Aug 2011 at 12:45

• Changed state: NeedMoreInfo

[GoogleCodeExporter]

Logkeys merely reports the following:
 <LShft>E32

In the editor which has focus, on the other hand, I get the following
(generated by the device):
CRYPTO-THING-0.8-ARC4-DROP2048:IVL0xa30x4f0xde0x9e0x820x150xca0x740x370xdc0x6c0x
8a0x3a0x130xd10x20xc10x9c0x2d0x9f0x5a0x990x510x6f0x310x470x00xa40x6d0x20xc90x5c:
KL:32:BASE32

I can see activity on event12 when the burst is sent from the device, as
well as when I manually type on the connected keyboard.

In summary, the event isn't silent, and logkeys is losing chunks of the
input.  It's possibly because of the speed at which the device sends it
across, compared to how slow a human types.  Might not be an issue for most
users of logkeys though.

Original comment by colm.p.o...@gmail.com on 1 Aug 2011 at 2:01

[GoogleCodeExporter]

could you please do in terminal:
sudo dd if=/dev/input/event12 of=~/event12.output bs=16

and then send the burst, and then Ctrl+C that terminal with dd, and then upload 
the event12.output file. that'll help debug.
with it, please attach the expected contents of burst, e.g. is 
"CRYPTO-THING-0.8-ARC4-..." the same string as you get if you press 
C-R-Y-P-T-O-... manually on Teensy keyboard (meaning the burst is actually 
exactly those characters)?
in that case, could you make the burst more exemplary, e.g. 
"abcdefghijklmnopqrstuvwxyz" or something like that? that would help debug. :-)

Original comment by kernc...@gmail.com on 1 Aug 2011 at 10:02

[GoogleCodeExporter]

The file is attached. The Teensy device has changed from event12 to event 13
this time, so that's what I captured.

The editor that had focus at the time captured the following:

jjjjabcdefghijklmnop

CRYPTO-THING-0.8-ARC4-DROP2048:IVL:32:IV:0xc10x520xfb0x380xe00x40xac0x6c0x120xe2
0x9c0x1f0xc50x540xc0xca0x820xc00x700x380xec0x2d0xe00x500x40xac0x6a0xb30x6c0x7c0x
1b0xb0:KL:32:BASE32

The logkeys log file captured the following:

Logging started ...

2011-08-02 11:07:40+0100 >  jjjjabcdefghijklmnop
2011-08-02 11:10:09+0100 > <LShft>E32
2011-08-02 11:10:18+0100 >

Note that I typed "jjjjabcdefghijklmnop" manually via the attached keyboard,
and then sent the burst via a button on the hardware.

The <LShft>E32 in the log is interesting.. it appears where the
"CRYPTO-THING-..."  should appear. Some form of error with that key
combination that logkeys can't handle, perchance?

Original comment by colm.p.o...@gmail.com on 2 Aug 2011 at 10:19

[GoogleCodeExporter]

sorry, you responded via email and Google obviously didn't recognize the 
attachment as such. can you please re-attach it here.

<LShift>E32 is interesting indeed. but instead of error, which ought to be 
marked as <E-%%> (%% a hexadecimal representation of erroneous byte), E32 means 
you pressed uppercase 'E' (with <LShift> modifier beforehand) followed by '3' 
and '2'. obviously wrong.

I would need to see that binary event output. that may shed more light.

Original comment by kernc...@gmail.com on 2 Aug 2011 at 2:07

[GoogleCodeExporter]

Apollo G's. 

File attached.

Original comment by colm.p.o...@gmail.com on 2 Aug 2011 at 5:23

Attachments:

• event13.output

[GoogleCodeExporter]

Just noticed. Silly me. the E32 is the end of the burst... 

...0xb30x6c0x7c0x1b0xb0:KL:32:BASE32

Original comment by colm.p.o...@gmail.com on 2 Aug 2011 at 7:37

[GoogleCodeExporter]

E32, indeed.
the problem is, logkeys takes too much time to process every keystroke (in your 
example above, to append the log with new timestamp on Enter key, for example) 
so that input event buffer, which can only hold so and so many characters, 
clears/rewrites in that time.
there's no usleep() in the main while loop that was there once, but the 
processing is still to slow, it appears.

the issue will be solved by using an logkeys-internal intermediate buffer that 
one thread will just copy to, and the other thread(s) will read and process 
from.

thanks for reporting. unfortunately, I don't know another quick fix for it.

Original comment by kernc...@gmail.com on 3 Aug 2011 at 1:35

• Changed state: Accepted

[GoogleCodeExporter]

ok, the alternative is to pipe the output from event device to program via a 
shell (and hence I suppose buffered) process, like so

pipe = popen("cat /dev/input/eventX", 'r');

then reading from this pipe instead of /dev/input/eventX directly.

I'll see which way to take when I think it through.

thanks again. :-)

Original comment by kernc...@gmail.com on 3 Aug 2011 at 1:40

[GoogleCodeExporter]

In theory, I could throttle the rate of data that I send through, but that's 
just like slapping a plaster on the issue, rather  than resolving the cause.  
It also wouldn't solve the issue for everyone.

Original comment by colm.p.o...@gmail.com on 3 Aug 2011 at 9:34