Custom logging reports wrong line number?

Hello,

For designing a special product, we have many (over 20) of Python scripts. To simplify trouble shooting, we use the logging Python module. Because it was difficult to control the activation/deactivation of the logging and the level of detail of the whole process over that many files (on file could have logging deactivated, another logging only errors, etc.), I wrote another module which regroup all the calls to the basic logging Python library, relying on the sys._getframe() method to get the caller line of code (otherwise I would always get my log function line number which kind of defeats the logging purpose!).

At first it seems to work but I found that it only reported the right line number when I run it from the Rhino Python Editor WITH a break point somewhere in the code (and continuing afterward). Without hitting a breakpoint (just pressing Play), it would always report the line 1!

Can anyone tell me:

  1. Why the Python sys._getframe() call behaves differently wether there is a breakpoint present or not.
  2. What can I do to fix it?

Regards,

P.S.: Attached are example of logging results I get with/without breakpoint and a streamlined version of my custom logging module (just run it in the Python Editor to reproduce the problem)

Bruno

MyLog_Bad_NoBreakPoint.txt (199 Bytes)
MyLog_Good_BreakpointAndContinue.txt (199 Bytes)
MyLogging.py (1.2 KB)

Hello,

In the following forum,

Stack trace enable only in debug?

I found a guy saying:

Ah – Rhino does not generate stack traces at all unless “debug” is
enabled. This is historical – I have no idea why it is not the default but
perhaps 10 years ago it was a big performance drain (seriously)…

That comment would seems to point in the direction that Rhino does not keep all the stack information if it’s not running with the Debugger attached… Is there a way to change this behavior? That would be very important for our process!

Bruno

Hi Bruno,

i think that topic and it’s mention of Rhino does not talk about the Cad software developed by McNeel but about Rhino, the open source implementation of JavaScript which is developed by Mozilla.

c.

My mistake… maybe it is closer to a previous post I did a long time ago:

How to debug scripts launched from RunPythonScript (e.g. in custom button)?

It seems there is something different about Rhino running in Debug vs Release that might be related to my problem (missing stacktrace line number information)…

Any idea?

Bruno

@bmartin, apart from what @stevebaer answered in the linked thread above i do not know anything about python’s debugging feature. I also never use breakpoints in the python editor, just extensive testing of all scripts and modules until i am not getting any errors :wink:

In your linked thread above you’re showing a dialog. Is your question about debugging errors happening in that dialog ? If yes, how did you write it and how do you open the form ? (modal or modeless).

c.

Try playing with the options in the python editor for frames and tracing. That may help

Yikes! I can’t imagine working without a debugger.

I am the debugger :smirk:

c.

2 Likes

Hello Clement,

I’m no longer using the dialog. Instead, I created specific buttons for each operation but the old problem explained in my other post still remains.

For example, when I press a specific button, I would like the editor to break in a function 2 or 3 call later (in a different .py file than the one that started the processing). I find this restriction really working against developers trying to extract coherent code into specific modules (.py files) and reusing these modules as building blocks for more complex operations implemented in other .py files…
@stevebaer, you don’t know how many times I would have gladly paid the performance price to be able to break even when the processing was not started form the editor! IMHO, this is a choice that should be put into the hands of the users/developers instead of automatically decided for them, even if used only during development. For example, in C++, you can decide to build your optimized code WITH the debug information still generated and usable…

BTW, I don’t seem to have the Tracing Enabled option in the editor? See:

Here is my version info:

Version 5 SR14 32-bit
(5.14.522.8390, 2017-05-22)

Well, that was not directly the point by I suspect that the same thing that was preventing the use of breakpoints in code used in release mode (not started from the editor) might also be stripping call stack line number information?

Thanks for your help, I’m still open to suggestions/workaround…

Bruno

Hi Bruno,

I am not 100% sure i understand the problem but you can import other modules from seperate py files and access the functions in them in your main script. If an error occurs in the module the respective path to the module should be printed to the command line along with the line the error occured in. I understand that if the script is not run from the editor, it will not print errors in the editor or use any breakpoints.

To get more specific error handling without using the editor you could work with try / except blocks or assert messages in each of the module functions. I do this with all delegates where Rhino does not do any error printing.

I also do not have this.

c.

Hello @clement,

Of course I’m aware we can import other modules (other .py files) and reuse them, that’s exactly what prompted my need to start the processing in one Master.py and have breakpoints activated in other imported Slave.py but when the Master.py script was not started by the debugger.

The debugging and stacktrace information issues are larger that the simple choice of error handling strategy (I use lots of asserts and try/except where appropriate). The most difficult problems to debug are not the ones that throw (which would be required for the try/except strategy to work) or assert but the ones that kind of runs correctly but gives wrong results. That’s in these cases where it’s very helpful to be able to break and look at the variable types/values to understand why a given algorithm doesn’t converge for example.

IMO, improving the development environment to facilitate debugging would go a long way in making Rhino developers more productive (at least one :wink:)

Regards,

Bruno

@dale, @stevebaer Any idea about what is happening to the line number information contained in the stacktrace while running without the Editor attached? Maybe there is another way to get this information than using this construct:

caller = sys._getframe(2) #Because I'm 2 function call deeper than where I want the info
linenumber = caller.f_lineno  #Always returns 1 without the debugger attached!

Any suggestion would be welcome!

Bruno

@bmartin
could you try Rhino WIP? @stevebaer updated the version of Python, it might have some implications. Also, the other option (Tracing) is available.

Can I install Rhino WIP side-by-side with my current Rhino 5.14? I would not want to disturb my old setup compare to what we have in production… Also, what Python version is Rhino WIP using?

Regards,

Bruno

Yes, you can. sys.version_info prints:

major=2, minor=7, micro=5, releaselevel='final', serial=0

sys.version, in turn,

2.7.5 (IronPython 2.7.5 (2.7.5.0) on .NET 4.0.30319.42000 (64-bit))