Create a log file for report messages

[janga1997]

It took me longer than expected, but it turned out to be straightforward in the end. (Because of the hierarchy of all the files in Blendyn is top down from base.py, the logging instance created in base.py works for all the report messages in all the modules)

I have kept the extension of the report file to be created as .err for the time being. Do suggest a suitable extension for the same.

This is how report messages are stored in the log file.

Sun, 07 May 2017 12:54:29 - ERROR - The .log file selected does not contain MBDyn nodes definitions
Sun, 07 May 2017 12:54:40 - ERROR - MBDyn labels file not found...
Sun, 07 May 2017 12:54:45 - INFO - Scene MBDyn data cleared.

[janga1997]

@zanoni-mbdyn The "not always imported into one another" part turned out to be irrelevant. Correct me if I am wrong, but root file in Blendyn is base.py, with all the other files being imported into base.py through a tree-like structure. That makes things easier, because the logger instance defined in base.py, which defines the formatting/name/extension of the log file, will work for logging calls in all files. That's how the logging module in Python works in multi files/modules cases like Blendyn.

[louisgag]

Check and works, but only reports non-error messages to the bylog file.

[janga1997]

@louisgag That's strange. The example I posted above is from a .bylog file that was created.

Do you maybe mean non-error messages from files other than base.py?

[louisgag]

That's possible. I only checked that 1) yes the bylog file gets created but 2) tried generating some random error (importing a file that does not exist) and it only showed in Blender's interface but not in the bylog file.

On 08-May-2017 10:47 AM, VSN Reddy Janga wrote:

Do you maybe mean non-error messages from files other than |base.py|?

-- Louis Gagnon, Ph.D. Postdoctoral fellow Dipartimento di Scienze e Tecnologie Aerospaziali Politecnico di Milano +39 02 2399 8642 http://louisgagnon.com/research/

[janga1997]

@louisgag Importing a results file (.mov, .nc) that does not exist, I think is not a report message generated by Blendyn? If that's the case, I cannot add a logging call to that report message.

[louisgag]

You're probably correct. I did a quick check and, at least some, Blendyn specific messages seem to indeed get reported in the bylog file.

On 08-May-2017 11:09 AM, VSN Reddy Janga wrote:

@louisgag https://github.com/louisgag Importing a results file (.mov, .nc) that does not exist, I think is not a report message generated by Blendyn? If that's the case, I cannot add a logging call to that report message.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/zanoni-mbdyn/blendyn/pull/14#issuecomment-299814089, or mute the thread https://github.com/notifications/unsubscribe-auth/ALuOfTjhiUWv2-Zrt06QGdgA-DLhH95kks5r3tu8gaJpZM4NTC71.

-- Louis Gagnon, Ph.D. Postdoctoral fellow Dipartimento di Scienze e Tecnologie Aerospaziali Politecnico di Milano +39 02 2399 8642 http://louisgagnon.com/research/

[zanoni-mbdyn]

Good. I tested the PR and it seems to work fine.

A few minor things:

• what if the user has two .blend files that are built on top of the same MBDyn model, and imports the same MBDyn output file into both of them (in separate Blender sessions, obviously)? Does the .bylog file get overwritten? If so, can we avoid this and just put a separator that indicates that a different Blender file is used in that specific session? If the file is not yet saved, we could ask the user to do so in order to enable logging, otherwise it will be disabled. This line (or lines) can also serve as a header to the file, that helps recognise it when reading it outside of Blendyn;
• once the .bylog file is created, load it in the Blender text editor so that the it can be looked up when an error or info message is missed;
• when we're done, we should really document this new feature in the wiki :)

[louisgag]

On 09-May-2017 09:19 AM, Andrea Zanoni wrote:

when we're done, we should really document this new feature in the wiki :)

Yes, making appropriate documentation to cover all the new features that your GSoC will bring to Blendyn is definitely a must. People need to know about all the cool things you'll be adding. -Louis

[janga1997]

@zanoni-mbdyn No the .bylog doesn't get overwritten in any case. It only gets appended. I thought adding the time would clear up doubts about which Blender file he was doing at that time, but I guess it is harder to keep track. I will figure out a way to include the blender file name into the .bylog file.

This line (or lines) can also serve as a header to the file, that helps recognise it when reading it outside of Blendyn;

I didn't quite understand.

[zanoni-mbdyn]

@janga1997 Suppose that a user that is not experienced casually opens a .bylog file while searching for another file (for example the .log file of an MBDyn output). If the .bylog file has a clear header, he can immediately understand what is going on. If not, he may be confused. It is just a plus, but I think it might be useful.

[janga1997]

@zanoni-mbdyn I've finally figure out how to handle logging messages from multiple .blend files at once. Instead of a header, would it be better to indicate the name of blend file in logging. And if the user hasn't saved the file, just name it as untitled.blend in the log messages, instead of not logging at all? Example

2017-05-11 19:52:46,202 - INFO - first.blend - Scene MBDyn data cleared.
2017-05-11 19:52:46,405 - INFO - first.blend - Scene MBDyn data cleared.
2017-05-11 19:53:04,782 - INFO - untitled.blend - MBDyn entities imported successfully
2017-05-11 19:53:13,979 - WARNING - untitled.blend - MBDyn labels file provided appears to not contain             correct labels.
2017-05-11 19:53:22,794 - INFO - first.blend - Scene MBDyn data cleared.

[janga1997]

And when the user does save the file, I will rename the blend file in the formatting of the logger using bpy.app.handlers.save_post . Maybe just a warning that You should probably save this to understand the log messages?

[louisgag]

I think these last two comments are actually for @zanoni-mbdyn

[zanoni-mbdyn]

@janga1997 Maybe the better way would be to just have a separate .log file for every .blend file. If the file is not yet saved, just call the log untitled.bylog.

We should be able, though, to remove the file if the user exits Blender without saving. I'm not sure how (and if) something like this might be accomplished.

[janga1997]

@zanoni-mbdyn Fine with me. But the .bylog file name should indicate both the name of the blend file and the name of the result file. So something like {blend_file}_{results_file}.bylog ?

If we delete the log file if the user exits Blender without saving, wouldn't that defeat the purpose of the log file to be created at all? I assume log files are for debugging after an animation in our case.

[zanoni-mbdyn]

@janga1997

But the .bylog file name should indicate both the name of the blend file and the name of the result file. So something like {blendfile}{results_file}.bylog ?

Yes, probably that's a better solution.

If we delete the log file if the user exits Blender without saving, wouldn't that defeat the purpose of the log file to be created at all? I assume log files are for debugging after an animation in our case.

I don't think so, If we load the contents of the file in the Text Editor during the current Blender session. It could be used as a reference in the current session, then discarded if the user chooses exit (i.e. to "discard" the current Blender file).

[janga1997]

@zanoni-mbdyn So I will get to work on displaying the messages in the text editor. I need a break from frying my mind on the Non integer frequencies feature.

[zanoni-mbdyn]

Just pick one issue and work on it, don't try to do 5 things at the same time! :)

[janga1997]

@zanoni-mbdyn Does the text editor need to be in constant sync with the log file? Because everytime there is a change in the .bylog file, a popup appears asking whether to reload from disk again. Is that going to be enough?

If not, and this is a case of constant sync, I will have to work this last part out after figuring out a solution for Adjusting timesteps automatically when the results file is changed. because I feel these both are related, where I have to keep track of a file changes and trigger Blender calls.

Meanwhile, I am pushing the changes till now. Logging to a file works smoothly.

[zanoni-mbdyn]

If I try the PR now, can I see the popups? I'll give you a feedback after seeing it in action...

[janga1997]

@zanoni-mbdyn Nopes. I just pushed the logging calls till now. Try entering bpy.ops.text.open(filename = 'path_to_bylog_file') in the scripting console. This will open up the bylog file in your text editor.

The popup will be a little red button on the left.

[zanoni-mbdyn]

Uhm, I see... It is now really a popup: a small red life buoy icon appears at the bottom of the editor asking the user to "resolve the conflict" by reloading the file.

Well documented, it could work. I'd still prefer to automatically reload the file every time, but if it is too much of a burden, it is fine to leave it as it is.

[zanoni-mbdyn]

Just out of curiosity: is it possible to open a file read-only in Blender? I'm scrolling through the text operators and it seems like the answer is "no"...

[janga1997]

Well, how about this, we leave it to the user right now to press the red button to reload the logFile. There are two other features in project based on auto-sync. When I work them out, I will see if I can automate this then.

[zanoni-mbdyn]

Agreed. When you're through, test and commit.

[janga1997]

Everything works out. Just one minor glitch. Some report messages were too long, so introducing a linebreak seems to add all the spaces to it. Example:-

                    message = "Could not spawn the Blender object assigned to node " \
                            + str(node.int_label)

is logged as

2017-05-12 22:09:47,739 - WARNING - MBDyn labels file provided appears to not contain             correct labels.

[zanoni-mbdyn]

Yeah I've noticed this behavior also when the messages are displayed in the Blender interface, or in the console. I'm not sure how to cure that...

[janga1997]

I thought I would have to use the textwrap library, but there is a simpler way to do it . Only now I have manually change it at every place in Blendyn.

[louisgag]

@janga1997 or do a sed/regexp search and replace in all of Blendyn's file at once... Example: https://unix.stackexchange.com/questions/78625/using-sed-to-find-and-replace-complex-string-preferrably-with-regex#78626

[janga1997]

I thought about that, but it's too varied to write a common script. Because this doesn't apply to all messages, only which are too long to fit in a line, and require a linebreak,. And some messages require more than one linebreak. Manual is the only way here.

[louisgag]

hmm, and why not textwrap, as you said? Seems to already come with Blender's python...

[janga1997]

Actually, adding a message = textwrap.dedent(message) above every self.report() call would make my task easier, but I thought preventing using a library when I can would be better. I will just go ahead with using textwrap then.

[zanoni-mbdyn]

@louisgag I think that @janga1997 had a point in trying to avoid using another external library just for this task ;)

But it's okay, it saved you a lot of work and I don't think it is much of an overhead, anyway.

I'll test later and merge in the case, thanks for the great work.

[janga1997]

@zanoni-mbdyn I ended up not using textwrap after all. I avoided the linebreak errors by just breaking up the strings at linebreaks, as it was before I touched them. Turns out I messed with their formatting when I started working on this issue.

[zanoni-mbdyn]

We're almost there... Is there a way to remove the untitled.bylog files that is created, if the user does not save the .blend file?

Another possibility, maybe much cleaner, has risen to my mind in this moment: why don't we write the log in a buffer loaded in the Text Editor during a session, and let the user decide if the final log is worth keeping or not? This could save us a lot of trouble.

We could think then of adding a BoolProperty that, if True (i.e. if checked in the UI) automatically saves the .bylog file before exiting Blender (this could be tricky because I seem to recall that there are no handlers triggered when exiting, in the Blender Python API).

@janga1997 what do you think?

[janga1997]

@zanoni-mbdyn An exit handler is definitely not possible in the context of Blender. But there seems to be a module atexit in the Python standard library, which could work. I'll have to check.

[janga1997]

@zanoni-mbdyn The atexit module does work. We can now delete log files of untitled blend files at Blender exit.

[janga1997]

And about loading the log messages into the Text Editor, I'm not sure if it would save us time. There still need to be logging calls at every report messages, so the only thing I would have to add is a bpy.ops.text.open(filepath = logFile) when setting the File Handler for the logging. So nothing changes really.

I will add the option to delete log messages upon exit. Just let me get a final thing straight.

1. For untitled blend files, delete log file after exit nevertheless of the option.
2. For saved blend files, delete log files only if user selects option to delete.

[zanoni-mbdyn]

And about loading the log messages into the Text Editor, I'm not sure if it would save us time. There still need to be logging calls at every report messages, so the only thing I would have to add is a bpy.ops.text.open(filepath = logFile) when setting the File Handler for the logging. So nothing changes really.

I was thinking about keeping the log lines in a Text Editor buffer (so that they remain automatically updated whenever a new log message is written, since there will be no need to reload an external file) and then flush the buffer to a new file once at the end of the session, if the user has not checked the option to delete the file at exit.

Just let me get a final thing straight. [...]

That's correct

[janga1997]

That would mean replacing all the logging calls with bpy.ops.text.insert ( ? ), and then doing a bpy.ops.text.save_as if the user wants the log files to be saved.

[zanoni-mbdyn]

Yes. I know it is tedious, but it is a better solution, in my opinion. I think that we could also include the messages that now are printed in the console.

[janga1997]

But the only difference I see is log messages showing up in the Text Editor , rather than an external file. The rest of the work, by and large remains same. I am still not sure about the perceived benefit.

[zanoni-mbdyn]

The user will not be required to load the file again to see the new messages

[janga1997]

Turns out the bpy.ops.text.* methods don't work in the VIEW_3D context (i.e. the one in which our UI exists). I have to switch context area every time by bpy.context.area.type == 'TEXT_EDITOR' But that just changes the screen to TEXT_EDITOR, and doesn't execute the rest of the script.

@zanoni-mbdyn Am I missing something?

[zanoni-mbdyn]

@janga1997 I don't know what methods are you specifically referring to, but I do something like this from the Python Console, in the VIEW_3D context

logtext = bpy.data.texts.new('test.log')
logtext.write('This is a log file\n')
logtext.write('--- First  log line\n')
logtext.write('--- Second log line\n')

And the I switch to the Text Editor and load test.log, this is what I get

This is a log file
--- First log line
--- Second log line

then I switched back to the VIEW_3D context and wrote another couple of (dummy) log lines:

logtext.write('--- Third log line\n')
logtext.write('--- Fourth log line\n')

and I got this in the Text Editor, without having to reload anything:

This is a log file
--- First log line
--- Second log line
--- Third log line
--- Fourth log line

[janga1997]

@zanoni-mbdyn Even though I got it to work in just base.py , I am not sure I could use the variable, logtext in this case across multiple modules. This sort of stuff is handled in the logging module, but I am not sure how to do it myself.

Instead I figured out a simpler solution, I hope, by attaching a custom handler( did not know about this before ) to our Logging instance, to write messages to the Text Editor in the above way , every time a logging call is triggered. Incidentally, it also saves me a ton of time. :) Try my new changes, it syncs perfectly.

[janga1997]

If this looks good enough, I will add the option to delete the log files upon exit.

[zanoni-mbdyn]

Yes, it seems to me like we're finally there :) Please add the delete option, and we'll (finally) merge.

[janga1997]

@zanoni-mbdyn I did add the delete option. See the commits just above your comment. I also changed the code a bit to rename the unititled log file ( and the file in the Text editor buffer ) upon saving.

[zanoni-mbdyn]

Sorry, I completely missed it. Ok, I'm merging now: thanks for the great work!