From: W. Trevor King <wking@drexel.edu>
Date: Mon, 21 Feb 2011 14:16:23 +0000 (-0500)
Subject: Add logger to trace function calls in Parsing.py.
X-Git-Url: http://git.tremily.us/?a=commitdiff_plain;h=ec64a4b11433daea06483047d816c4d9fab3c766;p=cython.git

Add logger to trace function calls in Parsing.py.
---

diff --git a/Cython/Compiler/Parsing.py b/Cython/Compiler/Parsing.py
index b8e54835..7c9c6a02 100644
--- a/Cython/Compiler/Parsing.py
+++ b/Cython/Compiler/Parsing.py
@@ -7,6 +7,7 @@
 import cython
 cython.declare(Nodes=object, ExprNodes=object, EncodedString=object)
 
+import logging
 import os
 import re
 import sys
@@ -22,6 +23,14 @@ from Cython import Utils
 import Future
 import Options
 
+
+_LOG = logging.getLogger('Cython.Compiler.Parsing')
+_LOG.setLevel(logging.CRITICAL)
+#_LOG.setLevel(logging.DEBUG)
+_LOG.addHandler(logging.StreamHandler())
+_LOG.handlers[-1].setLevel(logging.DEBUG)
+
+
 class Ctx(object):
     #  Parsing context
     level = 'other'
@@ -45,6 +54,7 @@ class Ctx(object):
         return ctx
 
 def p_ident(s, message = "Expected an identifier"):
+    _LOG.debug('p_ident(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'IDENT':
         name = s.systring
         s.next()
@@ -53,6 +63,7 @@ def p_ident(s, message = "Expected an identifier"):
         s.error(message)
 
 def p_ident_list(s):
+    _LOG.debug('p_ident_list(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     names = []
     while s.sy == 'IDENT':
         names.append(s.systring)
@@ -69,12 +80,14 @@ def p_ident_list(s):
 #------------------------------------------
 
 def p_binop_operator(s):
+    _LOG.debug('p_binop_operator(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     op = s.sy
     s.next()
     return op, pos
 
 def p_binop_expr(s, ops, p_sub_expr):
+    _LOG.debug('p_binop_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     n1 = p_sub_expr(s)
     while s.sy in ops:
         op, pos = p_binop_operator(s)
@@ -91,6 +104,7 @@ def p_binop_expr(s, ops, p_sub_expr):
 
 def p_lambdef(s, allow_conditional=True):
     # s.sy == 'lambda'
+    _LOG.debug('p_lambdef(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     if s.sy == ':':
@@ -112,11 +126,13 @@ def p_lambdef(s, allow_conditional=True):
 #lambdef_nocond: 'lambda' [varargslist] ':' test_nocond
 
 def p_lambdef_nocond(s):
+    _LOG.debug('p_lambdef_nocond(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     return p_lambdef(s, allow_conditional=False)
 
 #test: or_test ['if' or_test 'else' test] | lambdef
 
 def p_test(s):
+    _LOG.debug('p_test(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'lambda':
         return p_lambdef(s)
     pos = s.position()
@@ -133,6 +149,7 @@ def p_test(s):
 #test_nocond: or_test | lambdef_nocond
 
 def p_test_nocond(s):
+    _LOG.debug('p_test_nocond(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'lambda':
         return p_lambdef_nocond(s)
     else:
@@ -141,9 +158,11 @@ def p_test_nocond(s):
 #or_test: and_test ('or' and_test)*
 
 def p_or_test(s):
+    _LOG.debug('p_or_test(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     return p_rassoc_binop_expr(s, ('or',), p_and_test)
 
 def p_rassoc_binop_expr(s, ops, p_subexpr):
+    _LOG.debug('p_rassoc_binop_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     n1 = p_subexpr(s)
     if s.sy in ops:
         pos = s.position()
@@ -156,12 +175,14 @@ def p_rassoc_binop_expr(s, ops, p_subexpr):
 #and_test: not_test ('and' not_test)*
 
 def p_and_test(s):
+    _LOG.debug('p_and_test(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     #return p_binop_expr(s, ('and',), p_not_test)
     return p_rassoc_binop_expr(s, ('and',), p_not_test)
 
 #not_test: 'not' not_test | comparison
 
 def p_not_test(s):
+    _LOG.debug('p_or_test(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'not':
         pos = s.position()
         s.next()
@@ -173,6 +194,7 @@ def p_not_test(s):
 #comp_op: '<'|'>'|'=='|'>='|'<='|'<>'|'!='|'in'|'not' 'in'|'is'|'is' 'not'
 
 def p_comparison(s):
+    _LOG.debug('p_comparison(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     n1 = p_starred_expr(s)
     if s.sy in comparison_ops:
         pos = s.position()
@@ -185,12 +207,14 @@ def p_comparison(s):
     return n1
 
 def p_test_or_starred_expr(s):
+    _LOG.debug('p_test_or_starred_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == '*':
         return p_starred_expr(s)
     else:
         return p_test(s)
 
 def p_starred_expr(s):
+    _LOG.debug('p_starred_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     if s.sy == '*':
         starred = True
@@ -203,6 +227,7 @@ def p_starred_expr(s):
     return expr
 
 def p_cascaded_cmp(s):
+    _LOG.debug('p_cscaded_cmp(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     op = p_cmp_op(s)
     n2 = p_starred_expr(s)
@@ -213,6 +238,7 @@ def p_cascaded_cmp(s):
     return result
 
 def p_cmp_op(s):
+    _LOG.debug('p_cmp_op(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'not':
         s.next()
         s.expect('in')
@@ -239,40 +265,48 @@ comparison_ops = (
 #expr: xor_expr ('|' xor_expr)*
 
 def p_bit_expr(s):
+    _LOG.debug('p_bit_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     return p_binop_expr(s, ('|',), p_xor_expr)
 
 #xor_expr: and_expr ('^' and_expr)*
 
 def p_xor_expr(s):
+    _LOG.debug('p_xor_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     return p_binop_expr(s, ('^',), p_and_expr)
 
 #and_expr: shift_expr ('&' shift_expr)*
 
 def p_and_expr(s):
+    _LOG.debug('p_and_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     return p_binop_expr(s, ('&',), p_shift_expr)
 
 #shift_expr: arith_expr (('<<'|'>>') arith_expr)*
 
 def p_shift_expr(s):
+    _LOG.debug('p_shift_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     return p_binop_expr(s, ('<<', '>>'), p_arith_expr)
 
 #arith_expr: term (('+'|'-') term)*
 
 def p_arith_expr(s):
+    _LOG.debug('p_arith_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     return p_binop_expr(s, ('+', '-'), p_term)
 
 #term: factor (('*'|'/'|'%') factor)*
 
 def p_term(s):
+    _LOG.debug('p_term(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     return p_binop_expr(s, ('*', '/', '%', '//'), p_factor)
 
 #factor: ('+'|'-'|'~'|'&'|typecast|sizeof) factor | power
 
 def p_factor(s):
+    _LOG.debug('p_factor(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     # little indirection for C-ification purposes
     return _p_factor(s)
 
 def _p_factor(s):
+    _LOG.debug('_p_factor(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     sy = s.sy
     if sy in ('+', '-', '~'):
         op = s.sy
@@ -293,6 +327,7 @@ def _p_factor(s):
 
 def p_typecast(s):
     # s.sy == "<"
+    _LOG.debug('p_typecast(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     base_type = p_c_base_type(s)
@@ -314,6 +349,7 @@ def p_typecast(s):
 
 def p_sizeof(s):
     # s.sy == ident "sizeof"
+    _LOG.debug('p_sizeof(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     s.expect('(')
@@ -333,6 +369,7 @@ def p_sizeof(s):
 
 def p_yield_expression(s):
     # s.sy == "yield"
+    _LOG.debug('p_yield_expression(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     if s.sy != ')' and s.sy not in statement_terminators:
@@ -343,12 +380,14 @@ def p_yield_expression(s):
 
 def p_yield_statement(s):
     # s.sy == "yield"
+    _LOG.debug('p_yield_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     yield_expr = p_yield_expression(s)
     return Nodes.ExprStatNode(yield_expr.pos, expr=yield_expr)
 
 #power: atom trailer* ('**' factor)*
 
 def p_power(s):
+    _LOG.debug('p_power(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.systring == 'new' and s.peek()[0] == 'IDENT':
         return p_new_expr(s)
     n1 = p_atom(s)
@@ -363,6 +402,7 @@ def p_power(s):
 
 def p_new_expr(s):
     # s.systring == 'new'.
+    _LOG.debug('p_new_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     cppclass = p_c_base_type(s)
@@ -371,6 +411,7 @@ def p_new_expr(s):
 #trailer: '(' [arglist] ')' | '[' subscriptlist ']' | '.' NAME
 
 def p_trailer(s, node1):
+    _LOG.debug('p_trailer(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     if s.sy == '(':
         return p_call(s, node1)
@@ -387,6 +428,7 @@ def p_trailer(s, node1):
 
 def p_call_parse_args(s, allow_genexp = True):
     # s.sy == '('
+    _LOG.debug('p_call_parse_args(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     positional_args = []
@@ -435,6 +477,7 @@ def p_call_parse_args(s, allow_genexp = True):
     return positional_args, keyword_args, star_arg, starstar_arg
 
 def p_call_build_packed_args(pos, positional_args, keyword_args, star_arg):
+    _LOG.debug('p_call_build_packed_args()')
     arg_tuple = None
     keyword_dict = None
     if positional_args or not star_arg:
@@ -457,6 +500,7 @@ def p_call_build_packed_args(pos, positional_args, keyword_args, star_arg):
 
 def p_call(s, function):
     # s.sy == '('
+    _LOG.debug('p_call(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
 
     positional_args, keyword_args, star_arg, starstar_arg = \
@@ -481,6 +525,7 @@ def p_call(s, function):
 
 def p_index(s, base):
     # s.sy == '['
+    _LOG.debug('p_index(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     subscripts = p_subscript_list(s)
@@ -500,6 +545,7 @@ def p_index(s, base):
     return result
 
 def p_subscript_list(s):
+    _LOG.debug('p_subscript_list(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     items = [p_subscript(s)]
     while s.sy == ',':
         s.next()
@@ -514,6 +560,7 @@ def p_subscript(s):
     # Parse a subscript and return a list of
     # 1, 2 or 3 ExprNodes, depending on how
     # many slice elements were encountered.
+    _LOG.debug('p_subscript(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     start = p_slice_element(s, (':',))
     if s.sy != ':':
@@ -529,12 +576,14 @@ def p_subscript(s):
 def p_slice_element(s, follow_set):
     # Simple expression which may be missing iff
     # it is followed by something in follow_set.
+    _LOG.debug('p_slice_element(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy not in follow_set:
         return p_test(s)
     else:
         return None
 
 def expect_ellipsis(s):
+    _LOG.debug('expect_ellipsis(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     s.expect('.')
     s.expect('.')
     s.expect('.')
@@ -544,6 +593,7 @@ def make_slice_nodes(pos, subscripts):
     # by p_subscript_list into a list of ExprNodes,
     # creating SliceNodes for elements with 2 or
     # more components.
+    _LOG.debug('make_slice_nodes(subscripts=%s)' % (subscripts,))
     result = []
     for subscript in subscripts:
         if len(subscript) == 1:
@@ -553,6 +603,7 @@ def make_slice_nodes(pos, subscripts):
     return result
 
 def make_slice_node(pos, start, stop = None, step = None):
+    _LOG.debug('make_slice_node()')
     if not start:
         start = ExprNodes.NoneNode(pos)
     if not stop:
@@ -565,6 +616,7 @@ def make_slice_node(pos, start, stop = None, step = None):
 #atom: '(' [yield_expr|testlist_comp] ')' | '[' [listmaker] ']' | '{' [dict_or_set_maker] '}' | '`' testlist '`' | NAME | NUMBER | STRING+
 
 def p_atom(s):
+    _LOG.debug('p_atom(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     sy = s.sy
     if sy == '(':
@@ -623,6 +675,7 @@ def p_atom(s):
         s.error("Expected an identifier or literal")
 
 def p_int_literal(s):
+    _LOG.debug('p_int_literal(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     value = s.systring
     s.next()
@@ -654,6 +707,7 @@ def p_int_literal(s):
                              longness = longness)
 
 def p_name(s, name):
+    _LOG.debug('p_name(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     if not s.compile_time_expr and name in s.compile_time_env:
         value = s.compile_time_env.lookup_here(name)
@@ -679,6 +733,7 @@ def p_cat_string_literal(s):
     # A sequence of one or more adjacent string literals.
     # Returns (kind, bytes_value, unicode_value)
     # where kind in ('b', 'c', 'u', '')
+    _LOG.debug('p_cat_string_literal(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     kind, bytes_value, unicode_value = p_string_literal(s)
     if kind == 'c' or s.sy != 'BEGIN_STRING':
         return kind, bytes_value, unicode_value
@@ -705,6 +760,7 @@ def p_cat_string_literal(s):
     return kind, bytes_value, unicode_value
 
 def p_opt_string_literal(s, required_type='u'):
+    _LOG.debug('p_opt_string_literal(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'BEGIN_STRING':
         kind, bytes_value, unicode_value = p_string_literal(s, required_type)
         if required_type == 'u':
@@ -717,6 +773,7 @@ def p_opt_string_literal(s, required_type='u'):
         return None
 
 def check_for_non_ascii_characters(string):
+    _LOG.debug('check_for_non_ascii_characters(string=%s)' % (string))
     for c in string:
         if c >= u'\x80':
             return True
@@ -731,6 +788,7 @@ def p_string_literal(s, kind_override=None):
     # representations.
 
     # s.sy == 'BEGIN_STRING'
+    _LOG.debug('p_string_literal(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     is_raw = 0
     is_python3_source = s.context.language_level >= 3
@@ -836,6 +894,7 @@ def p_string_literal(s, kind_override=None):
 
 def p_list_maker(s):
     # s.sy == '['
+    _LOG.debug('p_list_maker(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     if s.sy == ']':
@@ -862,6 +921,7 @@ def p_list_maker(s):
         return ExprNodes.ListNode(pos, args = exprs)
 
 def p_comp_iter(s, body):
+    _LOG.debug('p_comp_iter(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'for':
         return p_comp_for(s, body)
     elif s.sy == 'if':
@@ -872,6 +932,7 @@ def p_comp_iter(s, body):
 
 def p_comp_for(s, body):
     # s.sy == 'for'
+    _LOG.debug('p_comp_for(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     kw = p_for_bounds(s, allow_testlist=False)
@@ -880,6 +941,7 @@ def p_comp_for(s, body):
 
 def p_comp_if(s, body):
     # s.sy == 'if'
+    _LOG.debug('p_comp_if(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     test = p_test_nocond(s)
@@ -892,6 +954,7 @@ def p_comp_if(s, body):
 
 def p_dict_or_set_maker(s):
     # s.sy == '{'
+    _LOG.debug('p_dict_or_set_maker(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     if s.sy == '}':
@@ -954,6 +1017,7 @@ def p_dict_or_set_maker(s):
 # NOTE: no longer in Py3 :)
 def p_backquote_expr(s):
     # s.sy == '`'
+    _LOG.debug('p_backquote_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     args = [p_test(s)]
@@ -968,6 +1032,7 @@ def p_backquote_expr(s):
     return ExprNodes.BackquoteNode(pos, arg = arg)
 
 def p_simple_expr_list(s, expr=None):
+    _LOG.debug('p_simple_expr_list(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     exprs = expr is not None and [expr] or []
     while s.sy not in expr_terminators:
         exprs.append( p_test(s) )
@@ -977,6 +1042,7 @@ def p_simple_expr_list(s, expr=None):
     return exprs
 
 def p_test_or_starred_expr_list(s, expr=None):
+    _LOG.debug('p_test_or_starred_expr_list(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     exprs = expr is not None and [expr] or []
     while s.sy not in expr_terminators:
         exprs.append( p_test_or_starred_expr(s) )
@@ -989,6 +1055,7 @@ def p_test_or_starred_expr_list(s, expr=None):
 #testlist: test (',' test)* [',']
 
 def p_testlist(s):
+    _LOG.debug('p_testlist(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     expr = p_test(s)
     if s.sy == ',':
@@ -1001,6 +1068,7 @@ def p_testlist(s):
 # testlist_star_expr: (test|star_expr) ( comp_for | (',' (test|star_expr))* [','] )
 
 def p_testlist_star_expr(s):
+    _LOG.debug('p_testlist_star_expr(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     expr = p_test_or_starred_expr(s)
     if s.sy == ',':
@@ -1013,6 +1081,7 @@ def p_testlist_star_expr(s):
 # testlist_comp: (test|star_expr) ( comp_for | (',' (test|star_expr))* [','] )
 
 def p_testlist_comp(s):
+    _LOG.debug('p_testlist_comp(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     expr = p_test_or_starred_expr(s)
     if s.sy == ',':
@@ -1026,6 +1095,7 @@ def p_testlist_comp(s):
 
 def p_genexp(s, expr):
     # s.sy == 'for'
+    _LOG.debug('p_genexp(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     loop = p_comp_for(s, Nodes.ExprStatNode(
         expr.pos, expr = ExprNodes.YieldExprNode(expr.pos, arg=expr)))
     return ExprNodes.GeneratorExpressionNode(expr.pos, loop=loop)
@@ -1040,12 +1110,14 @@ expr_terminators = (')', ']', '}', ':', '=', 'NEWLINE')
 
 def p_global_statement(s):
     # assume s.sy == 'global'
+    _LOG.debug('p_global_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     names = p_ident_list(s)
     return Nodes.GlobalNode(pos, names = names)
 
 def p_expression_or_assignment(s):
+    _LOG.debug('p_expression_or_assignment(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     expr_list = [p_testlist_star_expr(s)]
     while s.sy == '=':
         s.next()
@@ -1082,6 +1154,7 @@ def p_expression_or_assignment(s):
 
 def p_print_statement(s):
     # s.sy == 'print'
+    _LOG.debug('p_print_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     ends_with_comma = 0
     s.next()
@@ -1109,6 +1182,7 @@ def p_print_statement(s):
 
 def p_exec_statement(s):
     # s.sy == 'exec'
+    _LOG.debug('p_exec_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     args = [ p_bit_expr(s) ]
@@ -1124,6 +1198,7 @@ def p_exec_statement(s):
 
 def p_del_statement(s):
     # s.sy == 'del'
+    _LOG.debug('p_del_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     # FIXME: 'exprlist' in Python
@@ -1131,6 +1206,7 @@ def p_del_statement(s):
     return Nodes.DelStatNode(pos, args = args)
 
 def p_pass_statement(s, with_newline = 0):
+    _LOG.debug('p_pass_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.expect('pass')
     if with_newline:
@@ -1139,18 +1215,21 @@ def p_pass_statement(s, with_newline = 0):
 
 def p_break_statement(s):
     # s.sy == 'break'
+    _LOG.debug('p_break_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     return Nodes.BreakStatNode(pos)
 
 def p_continue_statement(s):
     # s.sy == 'continue'
+    _LOG.debug('p_continue_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     return Nodes.ContinueStatNode(pos)
 
 def p_return_statement(s):
     # s.sy == 'return'
+    _LOG.debug('p_return_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     if s.sy not in statement_terminators:
@@ -1161,6 +1240,7 @@ def p_return_statement(s):
 
 def p_raise_statement(s):
     # s.sy == 'raise'
+    _LOG.debug('p_raise_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     exc_type = None
@@ -1184,6 +1264,7 @@ def p_raise_statement(s):
 
 def p_import_statement(s):
     # s.sy in ('import', 'cimport')
+    _LOG.debug('p_import_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     kind = s.sy
     s.next()
@@ -1216,6 +1297,7 @@ def p_import_statement(s):
 
 def p_from_import_statement(s, first_statement = 0):
     # s.sy == 'from'
+    _LOG.debug('p_from_import_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     (dotted_name_pos, _, dotted_name, _) = \
@@ -1285,6 +1367,7 @@ def p_from_import_statement(s, first_statement = 0):
 imported_name_kinds = ('class', 'struct', 'union')
 
 def p_imported_name(s, is_cimport):
+    _LOG.debug('p_imported_name(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     kind = None
     if is_cimport and s.systring in imported_name_kinds:
@@ -1295,6 +1378,7 @@ def p_imported_name(s, is_cimport):
     return (pos, name, as_name, kind)
 
 def p_dotted_name(s, as_allowed):
+    _LOG.debug('p_dotted_name(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     target_name = p_ident(s)
     as_name = None
@@ -1307,6 +1391,7 @@ def p_dotted_name(s, as_allowed):
     return (pos, target_name, u'.'.join(names), as_name)
 
 def p_as_name(s):
+    _LOG.debug('p_as_name(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'IDENT' and s.systring == 'as':
         s.next()
         return p_ident(s)
@@ -1315,6 +1400,7 @@ def p_as_name(s):
 
 def p_assert_statement(s):
     # s.sy == 'assert'
+    _LOG.debug('p_assert_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     cond = p_test(s)
@@ -1329,6 +1415,7 @@ statement_terminators = (';', 'NEWLINE', 'EOF')
 
 def p_if_statement(s):
     # s.sy == 'if'
+    _LOG.debug('p_if_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     if_clauses = [p_if_clause(s)]
@@ -1340,6 +1427,7 @@ def p_if_statement(s):
         if_clauses = if_clauses, else_clause = else_clause)
 
 def p_if_clause(s):
+    _LOG.debug('p_if_clause(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     test = p_test(s)
     body = p_suite(s)
@@ -1347,6 +1435,7 @@ def p_if_clause(s):
         condition = test, body = body)
 
 def p_else_clause(s):
+    _LOG.debug('p_else_clause(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'else':
         s.next()
         return p_suite(s)
@@ -1355,6 +1444,7 @@ def p_else_clause(s):
 
 def p_while_statement(s):
     # s.sy == 'while'
+    _LOG.debug('p_while_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     test = p_test(s)
@@ -1366,6 +1456,7 @@ def p_while_statement(s):
 
 def p_for_statement(s):
     # s.sy == 'for'
+    _LOG.debug('p_for_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     kw = p_for_bounds(s, allow_testlist=True)
@@ -1375,6 +1466,7 @@ def p_for_statement(s):
     return Nodes.ForStatNode(pos, **kw)
 
 def p_for_bounds(s, allow_testlist=True):
+    _LOG.debug('p_for_bounds(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     target = p_for_target(s)
     if s.sy == 'in':
         s.next()
@@ -1418,6 +1510,7 @@ def p_for_bounds(s, allow_testlist=True):
         return {}
 
 def p_for_from_relation(s):
+    _LOG.debug('p_for_from_relation(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy in inequality_relations:
         op = s.sy
         s.next()
@@ -1426,6 +1519,7 @@ def p_for_from_relation(s):
         s.error("Expected one of '<', '<=', '>' '>='")
 
 def p_for_from_step(s):
+    _LOG.debug('p_for_from_step(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'by':
         s.next()
         step = p_bit_expr(s)
@@ -1436,6 +1530,7 @@ def p_for_from_step(s):
 inequality_relations = ('<', '<=', '>', '>=')
 
 def p_target(s, terminator):
+    _LOG.debug('p_target(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     expr = p_starred_expr(s)
     if s.sy == ',':
@@ -1451,9 +1546,11 @@ def p_target(s, terminator):
         return expr
 
 def p_for_target(s):
+    _LOG.debug('p_for_target(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     return p_target(s, 'in')
 
 def p_for_iterator(s, allow_testlist=True):
+    _LOG.debug('p_for_iterator(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     if allow_testlist:
         expr = p_testlist(s)
@@ -1463,6 +1560,7 @@ def p_for_iterator(s, allow_testlist=True):
 
 def p_try_statement(s):
     # s.sy == 'try'
+    _LOG.debug('p_try_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     body = p_suite(s)
@@ -1490,6 +1588,7 @@ def p_try_statement(s):
 
 def p_except_clause(s):
     # s.sy == 'except'
+    _LOG.debug('p_except_clause(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next()
     exc_type = None
@@ -1515,6 +1614,7 @@ def p_except_clause(s):
         pattern = exc_type, target = exc_value, body = body)
 
 def p_include_statement(s, ctx):
+    _LOG.debug('p_include_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     s.next() # 'include'
     unicode_include_file_name = p_string_literal(s, 'u')[2]
@@ -1538,6 +1638,7 @@ def p_include_statement(s, ctx):
         return Nodes.PassStatNode(pos)
 
 def p_with_statement(s):
+    _LOG.debug('p_with_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     s.next() # 'with'
     if s.systring == 'template' and not s.in_python_file:
         node = p_with_template(s)
@@ -1546,6 +1647,7 @@ def p_with_statement(s):
     return node
 
 def p_with_items(s):
+    _LOG.debug('p_with_items(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     if not s.in_python_file and s.sy == 'IDENT' and s.systring == 'nogil':
         state = s.systring
@@ -1571,6 +1673,7 @@ def p_with_items(s):
                               target = target, body = body)
 
 def p_with_template(s):
+    _LOG.debug('p_with_template(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     pos = s.position()
     templates = []
     s.next()
@@ -1596,6 +1699,7 @@ def p_with_template(s):
 
 def p_simple_statement(s, first_statement = 0):
     #print "p_simple_statement:", s.sy, s.systring ###
+    _LOG.debug('p_simple_statement(s=<s sy:%s systring:%s>)' % (s.sy, s.systring))
     if s.sy == 'global':
         node = p_global_statement(s)
     elif s.sy == 'print':
@@ -1629,6 +1733,8 @@ def p_simple_statement(s, first_statement = 0):
 def p_simple_statement_list(s, ctx, first_statement = 0):
     # Parse a series of simple statements on one line
     # separated by semicolons.
+    _LOG.debug('p_simple_statement_list(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     stat = p_simple_statement(s, first_statement = first_statement)
     if s.sy == ';':
         stats = [stat]
@@ -1643,6 +1749,8 @@ def p_simple_statement_list(s, ctx, first_statement = 0):
     return stat
 
 def p_compile_time_expr(s):
+    _LOG.debug('p_compile_time_expr(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     old = s.compile_time_expr
     s.compile_time_expr = 1
     expr = p_testlist(s)
@@ -1650,6 +1758,8 @@ def p_compile_time_expr(s):
     return expr
 
 def p_DEF_statement(s):
+    _LOG.debug('p_DEF_statement(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     denv = s.compile_time_env
     s.next() # 'DEF'
@@ -1663,6 +1773,8 @@ def p_DEF_statement(s):
     return Nodes.PassStatNode(pos)
 
 def p_IF_statement(s, ctx):
+    _LOG.debug('p_IF_statement(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     saved_eval = s.compile_time_eval
     current_eval = saved_eval
@@ -1690,6 +1802,8 @@ def p_IF_statement(s, ctx):
     return result
 
 def p_statement(s, ctx, first_statement = 0):
+    _LOG.debug('p_statement(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     decorators = None
     if s.sy == 'ctypedef':
         if ctx.level not in ('module', 'module_pxd'):
@@ -1763,6 +1877,8 @@ def p_statement(s, ctx, first_statement = 0):
 
 def p_statement_list(s, ctx, first_statement = 0):
     # Parse a series of statements separated by newlines.
+    _LOG.debug('p_statement_list(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     stats = []
     while s.sy not in ('DEDENT', 'EOF'):
@@ -1774,6 +1890,8 @@ def p_statement_list(s, ctx, first_statement = 0):
         return Nodes.StatListNode(pos, stats = stats)
 
 def p_suite(s, ctx = Ctx(), with_doc = 0, with_pseudo_doc = 0):
+    _LOG.debug('p_suite(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     s.expect(':')
     doc = None
@@ -1806,6 +1924,8 @@ def p_positional_and_keyword_args(s, end_sy_set, templates = None):
 
     Returns: (positional_args, keyword_args)
     """
+    _LOG.debug('p_positional_and_keyword_args(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     positional_args = []
     keyword_args = []
     pos_idx = 0
@@ -1858,12 +1978,16 @@ def p_positional_and_keyword_args(s, end_sy_set, templates = None):
 def p_c_base_type(s, self_flag = 0, nonempty = 0, templates = None):
     # If self_flag is true, this is the base type for the
     # self argument of a C method of an extension type.
+    _LOG.debug('p_c_base_type(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.sy == '(':
         return p_c_complex_base_type(s)
     else:
         return p_c_simple_base_type(s, self_flag, nonempty = nonempty, templates = templates)
 
 def p_calling_convention(s):
+    _LOG.debug('p_calling_convention(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.sy == 'IDENT' and s.systring in calling_convention_words:
         result = s.systring
         s.next()
@@ -1875,6 +1999,8 @@ calling_convention_words = ("__stdcall", "__cdecl", "__fastcall")
 
 def p_c_complex_base_type(s):
     # s.sy == '('
+    _LOG.debug('p_c_complex_base_type(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     s.next()
     base_type = p_c_base_type(s)
@@ -1884,7 +2010,8 @@ def p_c_complex_base_type(s):
         base_type = base_type, declarator = declarator)
 
 def p_c_simple_base_type(s, self_flag, nonempty, templates = None):
-    #print "p_c_simple_base_type: self_flag =", self_flag, nonempty
+    _LOG.debug('p_c_simple_base_type(s=<s sy:%s systring:%s>, self_flag=%s, nonempty=%s)'
+               % (s.sy, s.systring, self_flag, nonempty))
     is_basic = 0
     signed = 1
     longness = 0
@@ -1953,6 +2080,8 @@ def p_c_simple_base_type(s, self_flag, nonempty, templates = None):
 
 def p_buffer_or_template(s, base_type_node, templates):
     # s.sy == '['
+    _LOG.debug('p_buffer_or_template(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     s.next()
     # Note that buffer_positional_options_count=1, so the only positional argument is dtype.
@@ -1975,9 +2104,13 @@ def p_buffer_or_template(s, base_type_node, templates):
 
 
 def looking_at_name(s):
+    _LOG.debug('looking_at_name(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     return s.sy == 'IDENT' and not s.systring in calling_convention_words
 
 def looking_at_expr(s):
+    _LOG.debug('looking_at_expr(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.systring in base_type_start_words:
         return False
     elif s.sy == 'IDENT':
@@ -2014,10 +2147,13 @@ def looking_at_expr(s):
         return True
 
 def looking_at_base_type(s):
-    #print "looking_at_base_type?", s.sy, s.systring, s.position()
+    _LOG.debug('looking_at_base_type(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     return s.sy == 'IDENT' and s.systring in base_type_start_words
 
 def looking_at_dotted_name(s):
+    _LOG.debug('looking_at_dotted_name(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.sy == 'IDENT':
         name = s.systring
         s.next()
@@ -2044,6 +2180,8 @@ base_type_start_words = \
     basic_c_type_names + sign_and_longness_words + tuple(special_basic_c_types)
 
 def p_sign_and_longness(s):
+    _LOG.debug('p_sign_and_longness(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     signed = 1
     longness = 0
     while s.sy == 'IDENT' and s.systring in sign_and_longness_words:
@@ -2059,6 +2197,8 @@ def p_sign_and_longness(s):
     return signed, longness
 
 def p_opt_cname(s):
+    _LOG.debug('p_opt_cname(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     literal = p_opt_string_literal(s, 'u')
     if literal is not None:
         cname = EncodedString(literal)
@@ -2074,6 +2214,8 @@ def p_c_declarator(s, ctx = Ctx(), empty = 0, is_type = 0, cmethod_flag = 0,
     # the declarator must be nonempty. Otherwise we don't care.
     # If cmethod_flag is true, then if this declarator declares
     # a function, it's a C method of an extension type.
+    _LOG.debug('p_c_declarator(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     if s.sy == '(':
         s.next()
@@ -2103,6 +2245,8 @@ def p_c_declarator(s, ctx = Ctx(), empty = 0, is_type = 0, cmethod_flag = 0,
     return result
 
 def p_c_array_declarator(s, base):
+    _LOG.debug('p_c_array_declarator(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     s.next() # '['
     if s.sy != ']':
@@ -2114,6 +2258,8 @@ def p_c_array_declarator(s, base):
 
 def p_c_func_declarator(s, pos, ctx, base, cmethod_flag):
     #  Opening paren has already been skipped
+    _LOG.debug('p_c_func_declarator(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     args = p_c_arg_list(s, ctx, cmethod_flag = cmethod_flag,
                         nonempty_declarators = 0)
     ellipsis = p_optional_ellipsis(s)
@@ -2135,6 +2281,8 @@ supported_overloaded_operators = cython.set([
 
 def p_c_simple_declarator(s, ctx, empty, is_type, cmethod_flag,
                           assignable, nonempty):
+    _LOG.debug('p_c_simple_declarator(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     calling_convention = p_calling_convention(s)
     if s.sy == '*':
@@ -2202,6 +2350,8 @@ def p_c_simple_declarator(s, ctx, empty, is_type, cmethod_flag,
     return result
 
 def p_nogil(s):
+    _LOG.debug('p_nogil(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.sy == 'IDENT' and s.systring == 'nogil':
         s.next()
         return 1
@@ -2209,6 +2359,8 @@ def p_nogil(s):
         return 0
 
 def p_with_gil(s):
+    _LOG.debug('p_with_gil(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.sy == 'with':
         s.next()
         s.expect_keyword('gil')
@@ -2217,6 +2369,8 @@ def p_with_gil(s):
         return 0
 
 def p_exception_value_clause(s):
+    _LOG.debug('p_exception_value_clause(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     exc_val = None
     exc_check = 0
     if s.sy == 'except':
@@ -2244,6 +2398,8 @@ def p_c_arg_list(s, ctx = Ctx(), in_pyfunc = 0, cmethod_flag = 0,
                  nonempty_declarators = 0, kw_only = 0, annotated = 1):
     #  Comma-separated list of C argument declarations, possibly empty.
     #  May have a trailing comma.
+    _LOG.debug('p_c_arg_list(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     args = []
     is_self_arg = cmethod_flag
     while s.sy not in c_arg_list_terminators:
@@ -2257,6 +2413,8 @@ def p_c_arg_list(s, ctx = Ctx(), in_pyfunc = 0, cmethod_flag = 0,
     return args
 
 def p_optional_ellipsis(s):
+    _LOG.debug('p_optional_ellipsis(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.sy == '.':
         expect_ellipsis(s)
         return 1
@@ -2265,6 +2423,8 @@ def p_optional_ellipsis(s):
 
 def p_c_arg_decl(s, ctx, in_pyfunc, cmethod_flag = 0, nonempty = 0,
                  kw_only = 0, annotated = 1):
+    _LOG.debug('p_c_arg_decl(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     not_none = or_none = 0
     default = None
@@ -2312,6 +2472,8 @@ def p_c_arg_decl(s, ctx, in_pyfunc, cmethod_flag = 0, nonempty = 0,
         kw_only = kw_only)
 
 def p_api(s):
+    _LOG.debug('p_api(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.sy == 'IDENT' and s.systring == 'api':
         s.next()
         return 1
@@ -2364,6 +2526,8 @@ def p_cdef_block(s, ctx):
     return p_suite(s, ctx(cdef_flag = 1))
 
 def p_cdef_extern_block(s, pos, ctx):
+    _LOG.debug('p_cdef_extern_block(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if ctx.overridable:
         error(pos, "cdef extern blocks cannot be declared cpdef")
     include_file = None
@@ -2386,6 +2550,8 @@ def p_cdef_extern_block(s, pos, ctx):
 
 def p_c_enum_definition(s, pos, ctx):
     # s.sy == ident 'enum'
+    _LOG.debug('p_c_enum_definition(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     s.next()
     if s.sy == 'IDENT':
         name = s.systring
@@ -2413,6 +2579,8 @@ def p_c_enum_definition(s, pos, ctx):
         in_pxd = ctx.level == 'module_pxd')
 
 def p_c_enum_line(s, ctx, items):
+    _LOG.debug('p_c_enum_line(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.sy != 'pass':
         p_c_enum_item(s, ctx, items)
         while s.sy == ',':
@@ -2425,6 +2593,8 @@ def p_c_enum_line(s, ctx, items):
     s.expect_newline("Syntax error in enum item list")
 
 def p_c_enum_item(s, ctx, items):
+    _LOG.debug('p_c_enum_item(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     ctx = p_c_python_binding(s, ctx)
     name = p_ident(s)
@@ -2441,6 +2611,8 @@ def p_c_enum_item(s, ctx, items):
         in_pxd = ctx.level == 'module_pxd'))
 
 def p_c_struct_or_union_definition(s, pos, ctx):
+    _LOG.debug('p_c_struct_or_union_definition(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     packed = False
     if s.systring == 'packed':
         packed = True
@@ -2477,6 +2649,8 @@ def p_c_struct_or_union_definition(s, pos, ctx):
         in_pxd = ctx.level == 'module_pxd', packed = packed)
 
 def p_visibility(s, prev_visibility):
+    _LOG.debug('p_visibility(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     visibility = prev_visibility
     if s.sy == 'IDENT' and s.systring in ('extern', 'public', 'readonly'):
@@ -2488,6 +2662,8 @@ def p_visibility(s, prev_visibility):
     return visibility
 
 def p_c_modifiers(s):
+    _LOG.debug('p_c_modifiers(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.sy == 'IDENT' and s.systring in ('inline',):
         modifier = s.systring
         s.next()
@@ -2556,6 +2732,8 @@ def p_c_func_or_var_declaration(s, pos, ctx):
 
 def p_ctypedef_statement(s, ctx):
     # s.sy == 'ctypedef'
+    _LOG.debug('p_ctypedef_statement(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     s.next()
     visibility = p_visibility(s, ctx.visibility)
@@ -2582,6 +2760,8 @@ def p_ctypedef_statement(s, ctx):
             in_pxd = ctx.level == 'module_pxd')
 
 def p_decorators(s):
+    _LOG.debug('p_decorators(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     decorators = []
     while s.sy == 'DECORATOR':
         pos = s.position()
@@ -2601,6 +2781,8 @@ def p_decorators(s):
 
 def p_def_statement(s, decorators=None):
     # s.sy == 'def'
+    _LOG.debug('p_def_statement(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     s.next()
     name = EncodedString( p_ident(s) )
@@ -2620,6 +2802,8 @@ def p_def_statement(s, decorators=None):
         return_type_annotation = return_type_annotation)
 
 def p_varargslist(s, terminator=')', annotated=1):
+    _LOG.debug('p_varargslist(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     args = p_c_arg_list(s, in_pyfunc = 1, nonempty_declarators = 1,
                         annotated = annotated)
     star_arg = None
@@ -2640,6 +2824,8 @@ def p_varargslist(s, terminator=')', annotated=1):
     return (args, star_arg, starstar_arg)
 
 def p_py_arg_decl(s, annotated = 1):
+    _LOG.debug('p_py_arg_decl(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     name = p_ident(s)
     annotation = None
@@ -2650,6 +2836,8 @@ def p_py_arg_decl(s, annotated = 1):
 
 def p_class_statement(s, decorators):
     # s.sy == 'class'
+    _LOG.debug('p_class_statement(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     s.next()
     class_name = EncodedString( p_ident(s) )
@@ -2749,6 +2937,8 @@ def p_c_class_definition(s, pos,  ctx):
         body = body)
 
 def p_c_class_options(s):
+    _LOG.debug('p_c_class_options(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     objstruct_name = None
     typeobj_name = None
     s.expect('[')
@@ -2768,6 +2958,8 @@ def p_c_class_options(s):
     return objstruct_name, typeobj_name
 
 def p_property_decl(s):
+    _LOG.debug('p_property_decl(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     pos = s.position()
     s.next() # 'property'
     name = p_ident(s)
@@ -2775,6 +2967,8 @@ def p_property_decl(s):
     return Nodes.PropertyNode(pos, name = name, doc = doc, body = body)
 
 def p_doc_string(s):
+    _LOG.debug('p_doc_string(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     if s.sy == 'BEGIN_STRING':
         pos = s.position()
         kind, bytes_result, unicode_result = p_cat_string_literal(s)
@@ -2788,6 +2982,8 @@ def p_doc_string(s):
         return None
 
 def p_code(s, level=None):
+    _LOG.debug('p_code(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     body = p_statement_list(s, Ctx(level = level), first_statement = 1)
     if s.sy != 'EOF':
         s.error("Syntax error in statement [%s,%s]" % (
@@ -2797,6 +2993,8 @@ def p_code(s, level=None):
 COMPILER_DIRECTIVE_COMMENT_RE = re.compile(r"^#\s*cython:\s*((\w|[.])+\s*=.*)$")
 
 def p_compiler_directive_comments(s):
+    _LOG.debug('p_compiler_directive_comments(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     result = {}
     while s.sy == 'commentline':
         m = COMPILER_DIRECTIVE_COMMENT_RE.match(s.systring)
@@ -2811,6 +3009,8 @@ def p_compiler_directive_comments(s):
     return result
 
 def p_module(s, pxd, full_module_name):
+    _LOG.debug('p_module(<s sy:%s systring:%s>, pxd=%s, full_module_name=%s)'
+               % (s.sy, s.systring, pxd, full_module_name))
     pos = s.position()
 
     directive_comments = p_compiler_directive_comments(s)
@@ -2835,6 +3035,8 @@ def p_module(s, pxd, full_module_name):
 
 def p_cpp_class_definition(s, pos,  ctx):
     # s.sy == 'cppclass'
+    _LOG.debug('p_cpp_class_definition(s=<s sy:%s systring:%s>)'
+               % (s.sy, s.systring))
     s.next()
     module_path = []
     class_name = p_ident(s)
@@ -2933,4 +3135,3 @@ def print_parse_tree(f, node, level, key = None):
             f.write("%s]\n" % ind)
             return
     f.write("%s%s\n" % (ind, node))
-