Parser for HMI-AWoW logs.

parse_log.py

#!/usr/bin/env python
import argparse, logging
from collections import namedtuple
import numpy as np

# TODO: 
# - diff scan_code and key_id?

LOG_MOUSE_EVENTS = {
  512 : 'mouse movement',
  513 : 'mouse left pressed',
  514 : 'mouse left released',
  516 : 'mouse right pressed',
  517 : 'mouse right released',
  519 : 'mouse scroll button pressed',
  520 : 'mouse scroll button released',
  522 : 'mouse scroll'}

EVENTS = {
  8: ('key pressed [Back]', 8),
  9: ('key pressed [Tab]', 9),
  13: ('key pressed [Return]', 13),
  20: ('key pressed [Capital]', 20),
  27: ('key pressed [Escape]', 27),
  32: ('key pressed [Space]', 32),
  35: ('key pressed [End]', 35),
  36: ('key pressed [Home]', 36),
  37: ('key pressed [Left]', 37),
  38: ('key pressed [Up]', 38),
  39: ('key pressed [Right]', 39),
  40: ('key pressed [Down]', 40),
  45: ('key pressed [Insert]', 45),
  46: ('key pressed [Delete]', 46),
  48: ('key pressed [0]', 48),
  49: ('key pressed [1]', 49),
  50: ('key pressed [2]', 50),
  51: ('key pressed [3]', 51),
  52: ('key pressed [4]', 52),
  53: ('key pressed [5]', 53),
  54: ('key pressed [6]', 54),
  55: ('key pressed [7]', 55),
  56: ('key pressed [8]', 56),
  57: ('key pressed [9]', 57),
  65: ('key pressed [A]', 65),
  66: ('key pressed [B]', 66),
  67: ('key pressed [C]', 67),
  68: ('key pressed [D]', 68),
  69: ('key pressed [E]', 69),
  70: ('key pressed [F]', 70),
  71: ('key pressed [G]', 71),
  72: ('key pressed [H]', 72),
  73: ('key pressed [I]', 73),
  74: ('key pressed [J]', 74),
  75: ('key pressed [K]', 75),
  76: ('key pressed [L]', 76),
  77: ('key pressed [M]', 77),
  78: ('key pressed [N]', 78),
  79: ('key pressed [O]', 79),
  80: ('key pressed [P]', 80),
  81: ('key pressed [Q]', 81),
  82: ('key pressed [R]', 82),
  83: ('key pressed [S]', 83),
  84: ('key pressed [T]', 84),
  85: ('key pressed [U]', 85),
  86: ('key pressed [V]', 86),
  87: ('key pressed [W]', 87),
  88: ('key pressed [X]', 88),
  89: ('key pressed [Y]', 89),
  90: ('key pressed [Z]', 90),
  91: ('key pressed [Lwin]', 91),
  112: ('key pressed [F1]', 112),
  113: ('key pressed [F2]', 113),
  114: ('key pressed [F3]', 114),
  115: ('key pressed [F4]', 115),
  116: ('key pressed [F5]', 116),
  117: ('key pressed [F6]', 117),
  118: ('key pressed [F7]', 118),
  119: ('key pressed [F8]', 119),
  120: ('key pressed [F9]', 120),
  121: ('key pressed [F10]', 121),
  122: ('key pressed [F11]', 122),
  123: ('key pressed [F12]', 123),
  144: ('key pressed [Numlock]', 144),
  160: ('key pressed [Lshift]', 160),
  161: ('key pressed [Rshift]', 161),
  162: ('key pressed [Lcontrol]', 162),
  163: ('key pressed [Rcontrol]', 163),
  164: ('key pressed [Lmenu]', 164),
  165: ('key pressed [Rmenu]', 165),
  166: ('key pressed [Browser_Back]', 166),
  173: ('key pressed [Volume_Mute]', 173),
  174: ('key pressed [Volume_Down]', 174),
  175: ('key pressed [Volume_Up]', 175),
  187: ('key pressed [Oem_Plus]', 187),
  188: ('key pressed [Oem_Comma]', 188),
  189: ('key pressed [Oem_Minus]', 189),
  190: ('key pressed [Oem_Period]', 190),
  191: ('key pressed [Oem_2]', 191),
  192: ('key pressed [Oem_3]', 192),
  220: ('key pressed [Oem_5]', 220),
  222: ('key pressed [Oem_7]', 222),
  255: ('key pressed [None]', 255),
  513: ('mouse left pressed', 1),
  514: ('mouse left released', 2),
  516: ('mouse right pressed', 4),
  517: ('mouse right released', 5),
  519: ('mouse scroll button pressed', 7),
  520: ('mouse scroll button released', 8),
  522: ('mouse scroll', 10)}
   

log = logging.getLogger(__name__)

Event = namedtuple('Event', 'window desc time marker code x y wheel'.split())

def line_to_event(line):
  field = line.strip().split('\t')

  if field[-1] == 'key':
    time, marker, key_id, scan_code, key_name, _, window, _ = field
    return Event(window=window, desc='key pressed [%s]' % key_name, 
      time=int(time), marker=int(marker), code=int(key_id), x=None, y=None, 
      wheel=None)
    
  elif field[-1] == 'mouse':
    time, marker, code, pos, wheel, _, window, _ = field
    x, y = tuple(map(int, pos.strip('()').split(', ')))
    return Event(window=window, desc=LOG_MOUSE_EVENTS[int(code)],
      time=int(time), marker=int(marker), code=int(code), x=x, y=y, 
      wheel=int(wheel))
  else:
    logging.error('Event not recognized: "%s"!' % line)


def sanitize_logged_events(events):
  events = sorted([e for e in events if e], key=lambda e: e.time)
  events = [e for e in events if e.window == 'World of Warcraft']
  return events


if __name__ == '__main__':
  from pprint import pprint
  logging.basicConfig()

  # CLI:
  p = argparse.ArgumentParser()
  p.add_argument('logs', nargs='+')
  args = p.parse_args()

  # Read all events:
  events = []
  for log in args.logs:
    for line in open(log):
      events.append(line_to_event(line))

  # Display event definition for copy-pasting:
  rosetta = set([(e.code, (e.desc, e.marker)) for e in events if e])
  assert len(set(zip(*rosetta)[0])) == len(rosetta), 'Event codes not unique!'
  pprint(dict(rosetta))

Further questions:

• are events issued on key_down, or as well on key_up?
• what mouse events trigger a line in the log? Scrolling? Buttons? Movement?
• can a multiple keys share a single description (no?)?

1. key events are issued on key_down, I think -- definitely not both. Mouse buttons are apparently up & down (1&2, 4&5)
2. mouse actions: button presses are logged and tagged (markers). scrolling is only logged. movement is not logged, but coordinates during other mouse actions are in the log.
3. There might be overlap with numpad keys?

From Danny:
512 - mouse movement
513 - left mouse down
514 - left mouse up
516 - right mouse down
517 - right mouse up
519 - scroll button down
520 - scroll button up
522 - scroll

http://www.cs.unc.edu/Research/assist/doc/pyhook/public/pyHook.HookManager.HookConstants-class.html

Ok.. now I find that the time field is not necessarily increasing... any idea?

the time comes from pyHook's event.Time, which apparently comes straight from the Win32 EVENTMSG struct which is "milliseconds since last boot" (according to some mailinglist conversation). According to the pyHook manual it is "Seconds since the epoch when the even current", which is not really a sentence :o

I did recently learn about a mistake in my keylogger code (the key event catcher should return true), but I don't think that should affect incoming event attributes?

I can imagine that the messages get shuffled in Window's message passing system (I think they even can have different priorities). We can just sort events on time. My new WIP code can be seen in https://github.com/breuderink/eegtools/blob/hmi-wow/eegtools/data/hmi_wow.py .

What about the mistake in the keylogger? I can't oversee the consequences....

My planned strategy for matching the logs & events in the EDF is now to model the evens with a narrow Gaussian distribution, and do a small grid-search to find the difference in time and scaling deviations. Quite high-tech I would say :).

As far as I can see with the logging, it seems immediate, so there seem to be no detrimental consequences for that part? Otherwise I would have noticed the mistake earlier ;) But I guess it should have some effect somewhere .. :/

What meaning does the return value of the key-event catcher convey? Could you point me to the line in your logger and the relevant PyHook documentation? Perhaps then I know what to look for if the matching of logs & EDFs fails.

On Sun, Jul 22, 2012 at 9:55 AM, dplass ***@***.*** wrote: As far as I can see with the logging, it seems immediate, so there seem to be no detrimental consequences for that part? Otherwise I would have noticed the mistake earlier ;) But I guess it should have some effect somewhere .. :/ --- Reply to this email directly or view it on GitHub: https://gist.github.com/2687788

## twitter.com/#!/breuderink | github.com/breuderink | borisreuderink.nl

I read recently that if you return false, the key is not passed on to other programs [http://sourceforge.net/apps/mediawiki/pyhook/index.php?title=PyHook_Tutorial]
But apparently in my case it wasn't blocked, as WoW received all the necessary key presses.

Great! I think different subsystms are used. I know that windows does message passing for these events, that can be consumed (specified trough the return value in PyHook?). Probably a different path (DirectInput?) is used in WoW. But at least we don't have to worry about this :).

On Sun, Jul 22, 2012 at 4:30 PM, dplass ***@***.*** wrote: I read recently that if you return false, the key is not passed on to other programs [http://sourceforge.net/apps/mediawiki/pyhook/index.php?title=PyHook_Tutorial] But apparently in my case it wasn't blocked, as WoW received all the necessary key presses. --- Reply to this email directly or view it on GitHub: https://gist.github.com/2687788

## twitter.com/#!/breuderink | github.com/breuderink | borisreuderink.nl