def parse(self, line):
self.lineNumber += 1
# Local to the UHCI core
l = line.split("UHCI:")
if len(l) == 2:
m = re.search("- frame ([0-9]+) -", l[1])
if m:
self.frame = int(m.group(1))
# Don't let SOF markers start the clock
if self.epoch is not None:
self.eventQueue.put(Types.SOFMarker(self.parseRelativeTime(line),
self.frame, self.lineNumber))
return
# Local to the EHCI core
l = line.split("EHCI:")
if len(l) == 2:
m = re.search("Execute frame ([0-9]+)[\. ]", l[1])
if m:
self.frame = int(m.group(1))
# Don't let SOF markers start the clock
if self.epoch is not None:
self.eventQueue.put(Types.SOFMarker(self.parseRelativeTime(line),
self.frame, self.lineNumber))
return
# Generic analyzer URBs
l = line.split("USBIO:")
if len(l) == 2:
UsbIOParser.parse(self, l[1][:-1], self.parseRelativeTime(line),
self.frame, self.lineNumber)
else:
self.flush()
def handleTCP(self, event, data, datalen):
"""Decode an IPPROTO_TCP packet header, and log the payload."""
datalen -= 0x14
tcpHeader = Struct.Group(None,
Struct.UInt16BEHex("source"),
Struct.UInt16BEHex("dest"),
Struct.UInt32BE("seq"),
Struct.UInt32BE("ack_seq"),
Struct.UInt16BEHex("flags"),
Struct.UInt16BE("window"),
Struct.UInt16BEHex("checksum"),
Struct.UInt16BEHex("urg_ptr"))
data = tcpHeader.decode(data)
event.pushDecoded("iPhone TCP [%s -> %s] len=0x%04x" % (
self.portNumbers[tcpHeader.source],
self.portNumbers[tcpHeader.dest],
datalen,
))
event.appendDecoded("\nTCP Header:\n%s" % str(tcpHeader))
event.appendDecoded("\nTCP Payload:\n%s" % Types.hexDump(data))
# Look for a protocol-specific handler
for port in tcpHeader.source, tcpHeader.dest:
fn = getattr(self, "port_%s" % self.portNumbers[port], None)
if fn:
fn(event, data, datalen)
def port_lockdownd(self, event, data, datalen):
"""Handle lockdownd packets. These form a stream, which may or
may not line up with the underlying USB packets. Each
lockdownd packet is an XML plist, prefixed with a 32-bit
length.
"""
summary = []
self.lockdownBuffer += data
if datalen == 0:
# Leave the TCP decoder at the top of the stac
return
elif datalen != len(data):
# Nothing we can reliably do without the whole log.
self.lockdownBuffer = ""
summary.append("ERROR, incomplete log!")
elif (len(self.lockdownBuffer) >= 10 and
self.lockdownBuffer[0] == '\0' and
isascii(self.lockdownBuffer[1:])):
# I haven't seen this documented, but sometimes lockdownd sends
# ASCII error messages that are prefixed with one NUL byte.
summary.append("Message, %r" % self.lockdownBuffer[1:])
elif len(self.lockdownBuffer) >= 10 and self.lockdownBuffer[4:9] != "<?xml":
# Something else that isn't a plist?
self.lockdownBuffer = ""
summary.append("UNRECOGNIZED (SSL encrypted?)")
else:
# Decode all the packets we can
while len(self.lockdownBuffer) >= 4:
length = struct.unpack(">I", self.lockdownBuffer[:4])[0]
if len(self.lockdownBuffer) < length + 4:
break
packet = self.lockdownBuffer[4:length + 4]
self.lockdownBuffer = self.lockdownBuffer[length + 4:]
event.appendDecoded("\nComplete lockdownd packet:\n%s" %
Types.hexDump(packet))
kvFull = []
kvAbbrev = []
for k, v in plistlib.readPlistFromString(packet).items():
kvFull.append(" %s = %s" % (k, v))
if isinstance(v, plistlib.Data):
v = "(data)"
elif isinstance(v, dict):
v = "(dict)"
kvAbbrev.append("%s=%s" % (k, v))
event.appendDecoded("\nDecoded plist:\n%s" % "\n".join(kvFull))
summary.append("{%s}" % " ".join(kvAbbrev))
event.pushDecoded("lockdownd: %s" % (" ".join(summary) or "fragment"))
def createWidgets(self):
self.transactionWidgets = {}
self.pipes = {}
self.scroll = ScrollContainer()
self.scroll.hAdjust[0].set_property("step-increment", 20)
self.cursor = Types.Observable(-1)
# The ruler at the top is in charge of our time scale
self.ruler = Ruler()
TimeCursor(self.ruler, self.ruler, self.cursor)
self.ruler.canvas.set_hadjustment(self.scroll.hAdjust[0])
# The top heading holds the ruler, and a spacer aligned with the left heading
leftHeadingWidth = gtk.SizeGroup(gtk.SIZE_GROUP_HORIZONTAL)
spacer = gtk.Label()
leftHeadingWidth.add_widget(spacer)
topHeading = gtk.HBox(False)
topHeading.pack_start(spacer, False, padding=self.labelPadding)
topHeading.pack_start(gtk.VSeparator(), False)
topHeading.pack_start(self.ruler.canvas, True)
# Everything except the top heading scrolls vertically using a viewport
viewport = gtk.Viewport(None, self.scroll.vAdjust[0])
viewport.set_shadow_type(gtk.SHADOW_NONE)
viewport.set_size_request(1, 1)
viewportBox = gtk.VBox(False)
viewportBox.pack_start(topHeading, False)
viewportBox.pack_start(gtk.HSeparator(), False)
viewportBox.pack_start(viewport, True)
self.scroll.add(viewportBox)
# Gnome Canvas has really silly event grabbing semantics. To work around
# all this, we'll just grab all events before gnome-canvas sees them.
for widget in (viewport, self.ruler.canvas):
widget.add_events(gtk.gdk.POINTER_MOTION_HINT_MASK
| gtk.gdk.POINTER_MOTION_MASK
| gtk.gdk.BUTTON_PRESS_MASK)
for event in ('motion-notify-event', 'button-press-event',
'scroll-event'):
widget.connect_after(event, self.mouseEvent)
self.scroll.attachEvent(widget, horizontal=True)
# The left heading holds labels for each canvas in the stack
self.leftHeading = gtk.VBox(False)
leftHeadingWidth.add_widget(self.leftHeading)
# The viewport holds the left heading, then the main canvas stack
scrolledBox = gtk.HBox(False)
self.canvasList = []
self.canvasStack = gtk.VBox(False)
scrolledBox.pack_start(self.leftHeading,
False,
padding=self.labelPadding)
scrolledBox.pack_start(gtk.VSeparator(), False)
scrolledBox.pack_start(self.canvasStack, True)
viewport.add(scrolledBox)
return self.scroll
def flush(self):
"""Force any in-progress transactions to be completed. This should be
called when you know the USB analyzer is finished outputting
data, such as when a non-USBIO line appears in the log.
"""
if self.current.dir:
self.eventQueue.put(self.current)
self.current = Types.Transaction()
def beginUrb(self, pipe):
"""Simulate a new URB being created on the supplied pipe. This
begins a Down transaction and makes it pending and current.
"""
t = Types.Transaction()
t.dir = 'Down'
t.dev, t.endpt = pipe
t.timestamp = self.timestamp
t.frame = parseInt(self._frameAttrs, 'frameNumber')
t.status = 0
self.pipes[pipe] = t
self.pending[pipe] = t
self.current = t
def parse(self, line):
self.lineNumber += 1
tokens = line.split()
try:
# Extract the time, convert to seconds
nanotime = int(tokens[0])
if not self.epoch:
self.epoch = nanotime
timestamp = (nanotime - self.epoch) / 1000000000.0
# Detect the start- or end- prefix
name = tokens[1]
if name.startswith("begin-"):
name = name.split('-', 1)[1]
dirs = ('Down',)
elif name.startswith("end-"):
name = name.split('-', 1)[1]
dirs = ('Up',)
else:
dirs = ('Down', 'Up')
# Generate an 'endpoint' for the event name
try:
endpoint = self.nameEndpoints[name]
except KeyError:
endpoint = self.nextEp
self.nameEndpoints[name] = endpoint
self.nextEp = endpoint + 1
for dir in dirs:
trans = Types.Transaction()
trans.dir = dir
trans.timestamp = timestamp
trans.lineNumber = self.lineNumber
trans.endpt = endpoint
trans.dev = 0
trans.status = 0
trans.datalen = 0x1000
trans.appendDecoded(" ".join(tokens[1:]))
self.eventQueue.put(trans)
except:
print "Error on line %d:" % self.lineNumber
traceback.print_exc()
def flipUrb(self, pipe):
"""Begin the Up phase on a particular pipe. This
completes the Down transaction, and makes an Up
current (but not pending)
"""
del self.pending[pipe]
down = self.pipes[pipe]
self.eventQueue.put(down)
up = Types.Transaction()
up.dir = 'Up'
up.dev, up.endpt = pipe
# Up and Down transactions share setup data, if applicable
if down.hasSetupData():
up.data = down.data[:8]
self.pipes[pipe] = up
self.current = up
def createWidgets(self):
self.view = gtk.TreeView()
self.view.set_rules_hint(True)
self.view.connect("cursor-changed", self.onCursorChanged)
self.selectionInfo = Types.Observable()
self.onSelectionChanged(self.view.get_selection())
# Allow multiple select, and hook up a context menu
self.view.get_selection().set_mode(gtk.SELECTION_MULTIPLE)
self.view.get_selection().connect("changed", self.onSelectionChanged)
self.view.connect("button-press-event", self.onButtonPressed)
self.createModel()
self.createColumns()
self.eventToIter = {}
self.pipes = {}
return self.view
# FIXME: Determine the real max packet size, rather than
# using this hardcoded nonsense.
if len(self.current.data) & 0x3F:
self.completeUrb(pipe, id)
elif id in ('NYET', 'STALL'):
# Always complete on an error condition
self.completeUrb(pipe, id)
def characters(self, content):
# This extra level of indirection seems to be necessary, I guess Expat is
# binding our functions once at initialization.
if self.characterHandler:
self.characterHandler(content)
Types.psycoBind(EllisysXmlHandler)
class EllisysXmlParser:
"""Parses XML files exported from Ellisys Visual USB. This
is just a glue object that sets up an XML parser and
sends SAX events to the EllisysXmlHandler.
"""
lineOriented = False
def __init__(self, eventQueue):
self.eventQueue = eventQueue
self.xmlParser = xml.sax.make_parser()
self.xmlParser.setContentHandler(EllisysXmlHandler(eventQueue))
def parse(self, line):
def parse(self, line, timestamp=None):
self.lineNumber += 1
tokens = line.split()
iso = 0
try:
# Do a small stupid sanity check if this is a correct usbmon log line
try:
if len(tokens) < 4:
return
if not(int(tokens[0],16) and int(tokens[1]) and
(tokens[2] in ('S', 'C', 'E'))):
return
except:
print "Error on line %d:" % self.lineNumber
return
# Copied log file format description of the usbmon kernel
# facility You can find the original manual including how
# to use usbmon in your kernel sources: <linux
# sources>/Documentation/usb/usbmon.txt
#
# Copied text starts here:
# Any text format data consists of a stream of events,
# such as URB submission, URB callback, submission
# error. Every event is a text line, which consists of
# whitespace separated words. The number or position of
# words may depend on the event type, but there is a set
# of words, common for all types.
# Here is the list of words, from left to right:
# - URB Tag. This is used to identify URBs, and is
# normally an in-kernel address of the URB structure in
# hexadecimal, but can be a sequence number or any other
# unique string, within reason.
self.trans.lineNumber = self.lineNumber
# TODO Usbmon's timestamps can wrap. Annoyingly, they can wrap
# at either every 4096 seconds or (about) every 4296 seconds, see
# bugzilla.redhat.com/show_bug.cgi?id=574024 Let's wait for some
# feedback on that bugreport before adding (a possibly trivial)
# way to handle that.
# - Timestamp in microseconds, a decimal number. The
# timestamp's resolution depends on available clock, and
# so it can be much worse than a microsecond (if the
# implementation uses jiffies, for example).
# Extract the time, convert to seconds
microtime = int(tokens[1])
if not self.epoch:
self.epoch = microtime
timestamp = (microtime - self.epoch) / 1000000.0
self.trans.timestamp = timestamp
# - Event Type. This type refers to the format of the
# event, not URB type. Available types are: S -
# submission, C - callback, E - submission error.
if tokens[2] == 'S':
self.trans.dir = 'Down'
else:
self.trans.dir = 'Up'
# - "Address" word (formerly a "pipe"). It consists of
# four fields, separated by colons: URB type and
# direction, Bus number, Device address, Endpoint
# number. Type and direction are encoded with two bytes
# in the following manner:
#
# Ci Co Control input and output
# Zi Zo Isochronous input and output
# Ii Io Interrupt input and output
# Bi Bo Bulk input and output
#
# Bus number, Device address, and Endpoint are decimal
# numbers, but they may have leading zeros, for the sake
# of human readers.
#
# Note that older kernels seem to omit the bus number field.
# We can parse either format.
pipe = tokens[3].split(':')
self.trans.dev = int(pipe[-2])
self.trans.endpt = int(pipe[-1])
if pipe[0][1] == 'i' and self.trans.endpt != 0:
# Input endpoint
self.trans.endpt |= 0x80
if len(pipe) >= 4:
self.trans.dev += int(pipe[-3]) * 1000
# - URB Status word. This is either a letter, or several
# numbers separated by colons: URB status, interval,
# start frame, and error count. Unlike the "address"
# word, all fields save the status are
# optional. Interval is printed only for interrupt and
# isochronous URBs. Start frame is printed only for
# isochronous URBs. Error count is printed only for
# isochronous callback events.
#
# The status field is a decimal number, sometimes
# negative, which represents a "status" field of the
# URB. This field makes no sense for submissions, but is
# present anyway to help scripts with parsing. When an
# error occurs, the field contains the error code.
#
# In case of a submission of a Control packet, this
# field contains a Setup Tag instead of an group of
# numbers. It is easy to tell whether the Setup Tag is
# present because it is never a number. Thus if scripts
# find a set of numbers in this word, they proceed to
# read Data Length (except for isochronous URBs). If
# they find something else, like a letter, they read the
# setup packet before reading the Data Length or
# isochronous descriptors.
#
# - Setup packet, if present, consists of 5 words: one of
# each for bmRequestType, bRequest, wValue, wIndex,
# wLength, as specified by the USB Specification 2.0.
# These words are safe to decode if Setup Tag was
# 's'. Otherwise, the setup packet was present, but not
# captured, and the fields contain filler.
#
# - Number of isochronous frame descriptors and
# descriptors themselves. If an Isochronous transfer
# event has a set of descriptors, a total number of them
# in an URB is printed first, then a word per descriptor,
# up to a total of 5. The word consists of 3
# colon-separated decimal numbers for status, offset, and
# length respectively. For submissions, initial length is
# reported. For callbacks, actual length is reported.
if tokens[4] in ('s'):
# This is a setup packet
# Example data stage: 23 01 0010 0002 0040
self.trans.status = 0
data = ''.join(tokens[5:7])
# use VMX's byte ordering for wValue, wIndex and wLength
data = ''.join((data, tokens[7][2:4], tokens[7][0:2]))
data = ''.join((data, tokens[8][2:4], tokens[8][0:2]))
data = ''.join((data, tokens[9][2:4], tokens[9][0:2]))
self.trans.appendHexData(data)
# save the setup data to prepend it to the setup packet data stage
self.setupData = data
else:
status_word = tokens[4].split(':')
self.trans.status = int(status_word[0])
# check if this is a Callback (the 'Up' part of a transaction)
# on a CONTROL endpoint and prepend its Submission's (ie, its
# 'Down' part) setup packet, just as is done in the VMX logs.
if self.setupData and self.trans.endpt == 0 and \
self.trans.dir == 'Up':
self.trans.appendHexData(self.setupData)
self.setupData = None
# - Data Length. For submissions, this is the requested
# length. For callbacks, this is the actual length.
if len(tokens) >= 7:
if not pipe[0][0] == 'Z':
self.trans.datalen = int(tokens[5])
# The isochronous stuff is rather messy ... and probably
# fails with the legacy format. It also assumes input
# direction.
elif self.trans.dir == 'Down' and len(tokens) >= 8:
# skip two tokens:
# - number of isochronous frame descriptors
# - one descriptor
self.trans.datalen = int(tokens[7])
iso = 2
elif self.trans.dir == 'Up':
# The number of isochronous frame descriptors doesn't
# need to equal the number of following descriptors so
# we search for '=' and use the preceding token
try:
equal_sign = tokens.index('=')
if equal_sign > 6:
self.trans.datalen = int(tokens[equal_sign - 1])
iso = equal_sign - 6
except:
pass
# - Data tag. The usbmon may not always capture data, even
# if length is nonzero. The data words are present only
# if this tag is '='.
# - Data words follow, in big endian hexadecimal
# format. Notice that they are not machine words, but
# really just a byte stream split into words to make it
# easier to read. Thus, the last word may contain from
# one to four bytes. The length of collected data is
# limited and can be less than the data length report in
# Data Length word.
if tokens[6 + iso] in ('='):
self.trans.appendHexData(''.join(tokens[7 + iso:]))
self.eventQueue.put(self.trans)
self.trans = Types.Transaction()
# End of copied usbmon description text
# End of log file parsing
except:
print "Error on line %d:" % self.lineNumber
traceback.print_exc()
def __init__(self, eventQueue):
self.epoch = None
self.trans = Types.Transaction()
self.setupData = None
self.eventQueue = eventQueue
def __init__(self, eventQueue):
self.current = Types.Transaction()
self.eventQueue = eventQueue
class DiffWindow:
"""This is an alternate main window used to compare two log files"""
def __init__(self):
self.views = (Views.ViewContainer(), Views.ViewContainer())
self.status = Views.StatusMonitor()
self.needDiff = True
self.diffMatches = {}
self.status.completionCallbacks.append(self.loadingFinished)
# Two scrolling columns for our transaction lists,
# with one non-scrolled column in the middle for our diff markers.
# Everything scrolls vertically in unison.
listScroll = Views.ScrollContainer(hAxes=(True, False, True))
self.diffStatus = DiffStatusColumn()
self.diffStatus.view.set_size_request(20, 1)
self.diffStatus.view.set_vadjustment(listScroll.vAdjust[0])
frame = gtk.Frame()
frame.add(self.diffStatus.view)
listScroll.add(frame, 1, 0, 0)
timingBox = gtk.VBox(True)
paned = gtk.VPaned()
if Views.gnomecanvas:
paned.add1(timingBox)
paned.add2(listScroll)
paned.set_position(250)
self.events = {}
self.summaries = {}
transactionLists = []
for i, view in (
(0, self.views[0]),
(2, self.views[1]),
):
self.events[view] = []
self.summaries[view] = []
tlist = Views.TransactionList(view)
transactionLists.append(tlist)
tlist.view.set_hadjustment(listScroll.hAdjust[i])
tlist.view.set_vadjustment(listScroll.vAdjust[0])
tlist.root.set_size_request(1, 1)
listScroll.attachEvent(tlist.root)
frame = gtk.Frame()
frame.add(tlist.root)
listScroll.add(frame, i)
Views.TransactionDetailWindow(view).connectToList(tlist.view)
timing = Views.TimingDiagram(view)
self.status.watchCursor(timing.cursor)
timingBox.pack_start(timing.root)
# When a transaction is hilighted in one view,
# try to find a matching transaction in the other view
view.hilight.observers.append(self.matchHilights)
transactionLists[0].diffPartner = transactionLists[1]
transactionLists[1].diffPartner = transactionLists[0]
mainvbox = gtk.VBox(False)
mainvbox.pack_start(paned, True)
mainvbox.pack_start(self.status.statusbar, False)
self.window = gtk.Window()
self.window.set_default_size(1200, 900)
self.window.add(mainvbox)
self.window.show_all()
def handleEvent(self, event, view):
if isinstance(event, Types.Transaction):
self.events[view].append(event)
self.summaries[view].append(event.getDiffSummary())
view.handleEvent(event)
def loadingFinished(self):
"""We're idle. If we still need a diff, start one"""
if self.needDiff:
self.needDiff = False
self.bgDiff = BackgroundDiff(self.summaries[self.views[0]],
self.summaries[self.views[1]],
self.status.queue, self.diffCallback)
self.bgDiff.start()
def diffCallback(self, (i, j, n)):
"""This is called by BackgroundDiff when a new matching
block is discovered. The block starts at [i] and [j]
in our events/summaries lists, and extends for 'n' elements.
"""
self.diffStatus.match(i, j, n)
if n < 1:
return
for view, offset, otherView, otherOffset in (
(self.views[0], i, self.views[1], j),
(self.views[1], j, self.views[0], i),
):
# Generate DiffMarkers to show this match visually
view.handleEvent(
Types.DiffMarker(
(self.events[view][offset],
self.events[view][offset + n - 1]),
(self.events[otherView][otherOffset],
self.events[otherView][otherOffset + n - 1])))
# Correlate each transaction with its match
for index in xrange(n):
self.diffMatches[self.events[view][offset + index]] = (
otherView, self.events[otherView][otherOffset + index])
def __init__(self, completed):
self.epoch = None
self.trans = Types.Transaction()
self.trans.frame = 0
self.setupData = None
self.completed = completed
def __init__(self, completed):
self.current = Types.Transaction()
self.completed = completed
def __init__(self):
self.hilight = Types.Observable()
self.children = []
