bug(?) - unexpected frames being skipped in extract_stack with closures
all, I'm writing a function meant to print out the context of a given function call when executed - for example: 1. def main(): 2. 3. _st = stack_trace_closure("/path/to/log") 4. _st() 5. _st() would print out /path/to/file.py:4 /path/to/file.py:5 for each line when executed. Basic idea is to create a closure and associate that closure with a filename, then run that closure to print to the log without needing to give the filename over and over again. So far so good. But when I write this function, the frames given by getframeinfo or extract_stack skip the actual calling point of the function, instead giving back the *point where the closure was defined*. (in the above example, it would print /path/to/file.py:3, /path/to/file.py:3 instead of incrementing to show 4 and 5). However, when I insert a pdb statement, it gives me the expected calling frame where _st is actually called. What's going on here? It looks an awful lot like a bug to me, like an extra frame is being optimized out of of the closure's stack prematurely. I've tried this in python2.7 and python3.3, both show this. thanks much for any info, Ed code follows: --- def stack_trace_closure(message, file_name=None, frame=3): fh = open(file_name, "w+") def _helper(): return stack_trace(message, frame, fh) return _helper def stack_trace(message _frame, fh): _bt = traceback.extract_stack() fh.write( "%s:%s - %s" % (_bt[_frame][0], _bt[_frame][1], _message))
Hi Ed, Your note probably won't receive any other reply than this, because the python-dev list is specifically for discussions about the development _of_, rather than _with_, Python. A more appropriate forum is probably the Python list (python-list@python.org), about which you can discover more details at Python-list Info Page <https://mail.python.org/mailman/listinfo/python-list>. Kind regards, Steve Holden On Thu, Jun 20, 2019 at 3:40 AM Ed Peschko <horos22@gmail.com> wrote:
all,
I'm writing a function meant to print out the context of a given function call when executed - for example:
1. def main(): 2. 3. _st = stack_trace_closure("/path/to/log") 4. _st() 5. _st()
would print out
/path/to/file.py:4 /path/to/file.py:5
for each line when executed. Basic idea is to create a closure and associate that closure with a filename, then run that closure to print to the log without needing to give the filename over and over again.
So far so good. But when I write this function, the frames given by getframeinfo or extract_stack skip the actual calling point of the function, instead giving back the *point where the closure was defined*. (in the above example, it would print /path/to/file.py:3, /path/to/file.py:3 instead of incrementing to show 4 and 5).
However, when I insert a pdb statement, it gives me the expected calling frame where _st is actually called.
What's going on here? It looks an awful lot like a bug to me, like an extra frame is being optimized out of of the closure's stack prematurely.
I've tried this in python2.7 and python3.3, both show this.
thanks much for any info,
Ed
code follows: ---
def stack_trace_closure(message, file_name=None, frame=3):
fh = open(file_name, "w+")
def _helper(): return stack_trace(message, frame, fh)
return _helper
def stack_trace(message _frame, fh):
_bt = traceback.extract_stack()
fh.write( "%s:%s - %s" % (_bt[_frame][0], _bt[_frame][1], _message)) _______________________________________________ Python-Dev mailing list -- python-dev@python.org To unsubscribe send an email to python-dev-leave@python.org https://mail.python.org/mailman3/lists/python-dev.python.org/ Message archived at https://mail.python.org/archives/list/python-dev@python.org/message/4MKHPCRN...
Steven, Yes and I posted to python-dev for a reason - I'm almost positive that this is a bug - or at least an inconsistency - in how python handles stack frames WRT closures in some instances. In fact, the reason I posted is because we hit this inconsistency in handling production code - we need to have a reliable stack trace for all the functions we call in logs so we can better track down issues when they occur and be able to tie those issues to underlying code. If I add a pdb.set_trace() to the location inside the closure, I get a different - in fact the correct - stack trace. Otherwise, like I said, the stack trace points back to the place where the closure was defined, not the actual place the closure was called. Unfortunately, it looks like this bug is not in a simple example that I can readily reproduce (I just tried). so if I see it again i'll try to simplify it to a point where it still manifests and post that. Ed On Fri, Jun 21, 2019 at 1:35 AM Steve Holden <steve@holdenweb.com> wrote:
Hi Ed,
Your note probably won't receive any other reply than this, because the python-dev list is specifically for discussions about the development _of_, rather than _with_, Python.
A more appropriate forum is probably the Python list (python-list@python.org), about which you can discover more details at Python-list Info Page.
Kind regards, Steve Holden
On Thu, Jun 20, 2019 at 3:40 AM Ed Peschko <horos22@gmail.com> wrote:
all,
I'm writing a function meant to print out the context of a given function call when executed - for example:
1. def main(): 2. 3. _st = stack_trace_closure("/path/to/log") 4. _st() 5. _st()
would print out
/path/to/file.py:4 /path/to/file.py:5
for each line when executed. Basic idea is to create a closure and associate that closure with a filename, then run that closure to print to the log without needing to give the filename over and over again.
So far so good. But when I write this function, the frames given by getframeinfo or extract_stack skip the actual calling point of the function, instead giving back the *point where the closure was defined*. (in the above example, it would print /path/to/file.py:3, /path/to/file.py:3 instead of incrementing to show 4 and 5).
However, when I insert a pdb statement, it gives me the expected calling frame where _st is actually called.
What's going on here? It looks an awful lot like a bug to me, like an extra frame is being optimized out of of the closure's stack prematurely.
I've tried this in python2.7 and python3.3, both show this.
thanks much for any info,
Ed
code follows: ---
def stack_trace_closure(message, file_name=None, frame=3):
fh = open(file_name, "w+")
def _helper(): return stack_trace(message, frame, fh)
return _helper
def stack_trace(message _frame, fh):
_bt = traceback.extract_stack()
fh.write( "%s:%s - %s" % (_bt[_frame][0], _bt[_frame][1], _message)) _______________________________________________ Python-Dev mailing list -- python-dev@python.org To unsubscribe send an email to python-dev-leave@python.org https://mail.python.org/mailman3/lists/python-dev.python.org/ Message archived at https://mail.python.org/archives/list/python-dev@python.org/message/4MKHPCRN...
If you believe this is a bug then please file an issue at bugs.python.org so it isn't lost.
If you believe this is a bug then please open an issue at bugs.python.org so we don't lose track of it. On Fri, Jun 21, 2019 at 11:09 AM Ed Peschko <horos22@gmail.com> wrote:
Steven,
Yes and I posted to python-dev for a reason - I'm almost positive that this is a bug - or at least an inconsistency - in how python handles stack frames WRT closures in some instances. In fact, the reason I posted is because we hit this inconsistency in handling production code - we need to have a reliable stack trace for all the functions we call in logs so we can better track down issues when they occur and be able to tie those issues to underlying code.
If I add a pdb.set_trace() to the location inside the closure, I get a different - in fact the correct - stack trace. Otherwise, like I said, the stack trace points back to the place where the closure was defined, not the actual place the closure was called.
Unfortunately, it looks like this bug is not in a simple example that I can readily reproduce (I just tried). so if I see it again i'll try to simplify it to a point where it still manifests and post that.
Ed
On Fri, Jun 21, 2019 at 1:35 AM Steve Holden <steve@holdenweb.com> wrote:
Hi Ed,
Your note probably won't receive any other reply than this, because the
python-dev list is specifically for discussions about the development _of_, rather than _with_, Python.
A more appropriate forum is probably the Python list (
python-list@python.org), about which you can discover more details at Python-list Info Page.
Kind regards, Steve Holden
On Thu, Jun 20, 2019 at 3:40 AM Ed Peschko <horos22@gmail.com> wrote:
all,
I'm writing a function meant to print out the context of a given function call when executed - for example:
1. def main(): 2. 3. _st = stack_trace_closure("/path/to/log") 4. _st() 5. _st()
would print out
/path/to/file.py:4 /path/to/file.py:5
for each line when executed. Basic idea is to create a closure and associate that closure with a filename, then run that closure to print to the log without needing to give the filename over and over again.
So far so good. But when I write this function, the frames given by getframeinfo or extract_stack skip the actual calling point of the function, instead giving back the *point where the closure was defined*. (in the above example, it would print /path/to/file.py:3, /path/to/file.py:3 instead of incrementing to show 4 and 5).
However, when I insert a pdb statement, it gives me the expected calling frame where _st is actually called.
What's going on here? It looks an awful lot like a bug to me, like an extra frame is being optimized out of of the closure's stack prematurely.
I've tried this in python2.7 and python3.3, both show this.
thanks much for any info,
Ed
code follows: ---
def stack_trace_closure(message, file_name=None, frame=3):
fh = open(file_name, "w+")
def _helper(): return stack_trace(message, frame, fh)
return _helper
def stack_trace(message _frame, fh):
_bt = traceback.extract_stack()
fh.write( "%s:%s - %s" % (_bt[_frame][0], _bt[_frame][1],
_message))
_______________________________________________ Python-Dev mailing list -- python-dev@python.org To unsubscribe send an email to python-dev-leave@python.org https://mail.python.org/mailman3/lists/python-dev.python.org/ Message archived at https://mail.python.org/archives/list/python-dev@python.org/message/4MKHPCRN...
Python-Dev mailing list -- python-dev@python.org To unsubscribe send an email to python-dev-leave@python.org https://mail.python.org/mailman3/lists/python-dev.python.org/ Message archived at https://mail.python.org/archives/list/python-dev@python.org/message/DQBKRUI5...
participants (3)
-
Brett Cannon
-
Ed Peschko
-
Steve Holden