GSoC 2020: Info Editor Improvements - Discussion and Suggestions (logs, reports & friends)

Generally fine with those rules, although I would not confuse debug flags with log level (verbosity).

Debug flags allow you to completely turn on or off some parts of the logging (done through printf currently most of the time), this is not the same and imho should work in a complementary way with log verbosity?

Personally I would just create new logger. If you want to debug only menus, just do logger "wm.menus" instead:

if (G.debug & G_DEBUG_WM) {
    printf("%s: opening menu \"%s\"\n", __func__, mt->idname);
}

I would like to hear your thoughts on logs in 1st party libraries (libraries in /intern). Ghost in particular has no consistency.

1 Like

gpu, ghost, depgrah are on my todo list. I started de-printf-ing from /source.

So far (on branch) I gave some love to /source: window manager (new log wm.session - save, autosave), blenfont and various minor prints in blenkernel

I am mostly converting existing prints to logs, and removing the ones that make no sense, I tried avoiding huge changes as I am not super familiar with code.

In /intern i tried adding logs for /guardedalloc but failed so far due to circular dependency on clog, I do not want to deal with this for now. This is the only case of circular dependency in intern and i had to start from it…

General approach is to find prints, add log (or multiple), add various verbosities.

In what way is it inconsistent? Is it prints mixed with logs or do you mean the contents of what is being logged? If you tell me more I can probably make your life easier.

2 Likes

@JerzyGorski In this very moment I am tweaking logs in rendering. In code there is struct RenderStats that is printed every 25 samples. in current blender logs can be printed only in background mode, I am going to make them dependent on logger. This is (the most verbose) log from rendering 3 frames. Remeber that logs finely controlled. Should I make this log in parse-able format? Does anyone cares?

INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:197 render_print_save_message: Saved: '/tmp/0001.png'
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2305 do_write_image_or_movie:  Time: 00:00.75
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2315 do_write_image_or_movie:  (Saving: 00:00.40)
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.31M (Peak 134.41M) | Time:00:00.04 |  Syncing Cube |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.32M (Peak 134.41M) | Time:00:00.04 |  Syncing Light |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.32M (Peak 134.41M) | Time:00:00.04 |  Syncing Camera |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.31M (Peak 134.41M) | Time:00:00.05 |  Rendering 1 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.31M (Peak 134.41M) | Time:00:00.17 |  Rendering 26 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.31M (Peak 134.41M) | Time:00:00.27 |  Rendering 51 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:2 Mem:104.31M (Peak 134.41M) | Time:00:00.31 |  Rendering 64 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:197 render_print_save_message: Saved: '/tmp/0002.png'
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2305 do_write_image_or_movie:  Time: 00:01.26
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2315 do_write_image_or_movie:  (Saving: 00:00.27)
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.31M (Peak 134.41M) | Time:00:00.03 |  Syncing Cube |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.32M (Peak 134.41M) | Time:00:00.04 |  Syncing Light |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.32M (Peak 134.41M) | Time:00:00.04 |  Syncing Camera |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.31M (Peak 134.41M) | Time:00:00.05 |  Rendering 1 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.31M (Peak 134.41M) | Time:00:00.14 |  Rendering 26 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.31M (Peak 134.41M) | Time:00:00.22 |  Rendering 51 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
VERBOSE:1 (render.stats): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/external_engine.c:483 RE_engine_update_stats: Fra:3 Mem:104.31M (Peak 134.41M) | Time:00:00.26 |  Rendering 64 / 64 samples |Sce: Scene Ve:0 Fa:0 La:0
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:197 render_print_save_message: Saved: '/tmp/0003.png'
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2305 do_write_image_or_movie:  Time: 00:01.20
INFO (render): /home/mat/blender-sources/blender-src/source/blender/render/intern/source/pipeline.c:2315 do_write_image_or_movie:  (Saving: 00:00.28)

This is very new, it is not even commited.

There are some user experience quarks regarding log related UI that I will address in this post.

Enable disable logs from user preferences

Corner case: those values can be overridden from command line, but we still want to store them in preferences.

Solutions: Dedicated buttons for saving log preferences. These settings are omitted from default save mechanism. Add presets as a bonus.

image

4 Likes

I added all possible report types to UI as experiment. This is a bit more than in https://developer.blender.org/D6926. We have them defined in code, we just never bothered to make a UI for it.
Zrzut ekranu z 2020-08-06 12-09-47

7 Likes

I am trying to create some sensible filter UI for logging.

I would like to include features:

  • filter log severity (as enum or flag enum)
  • separate search fields log type, file line, log function
    – the UI is borrowed from this:
    image
  • ideally I would like to filter verbosity by ranges, but I can not figure out sensible UI for this king of feature

I am not sure how to expose log message formatting, so far I went with flag approach.

As for the context menu I am planning operations:

  • exclude log type/function/file/this line
  • sync selection - across all open info editors select the next visible log entry
  • copy all/file
3 Likes

If you’re including python errors, have you considered clicking on an error report would scroll to that line in the script in the Text Editor?

1 Like

Ghost’s logging (really printing) is enabled up by either macro’ed printf statements enabled by CMake flags, naked printf/couts, or as a runtime argument, but which is relied upon seems to be somewhat platform specific (e.g. the runtime argument seems to only be used for Linux).

In my case I’d like a clean way to log Wintab information in Ghost - see D7840. Ideally I’d like to isolate it from the noise of other Ghost-related debug information.

1 Like

Currently on python error text is being scrolled (at least in some conditions). There is no way to save any additional information in report. I can see this feature usefull, but currently it is hard to implement in clean way

2 Likes

I really like your project, you have done wonders with the Info editor or at least the UI with filtering, even if its the template and not yet implemented in code yet, looks really cool now! Thanks.

5 Likes

Filtering implementation is coming this week. Yesterday I added add,remove logic around filter boxes:
image
I wonder if filter boxes should have match case, use glob buttons…

1 Like

I am wondering how will you implement it without cluttering the UI, based on context?
having Match Case with a checkbox on the top, based on the currently selected Filter box, one can select and deselect it for each box, so you will have to save some state and maybe even allow for multiple selection for Filter boxes(?). This is as opposed to each Filter Box having its own match case. Is this close to your plan? and the currently selected Filter Box will have an orange or some colored selection around it. By “glob” buttons you mean “global”? or is it a button type?

2 Likes

there are 3-4 functionalities that i want to pack in filter UI/UX:

  • negate pattern - can be a button, or just sign in text glob (^ to negate pattern, same as in blender command line args)
  • match case
  • use glob - use globbing (pattern matching, wildcards) - sorry, nerdy stuff - in short: * match any character, ^ - negate pattern
  • match exact - match only words, do not match subset of string (need t verify naming of this one)

The last 2 might become one, I must deep dive into details.

Use glob can be always enabled, it does not have to be even an option, need to test it with user scenarios.
My first thoughts were to add buttons as below. Here are buttons for use case and use glob.
EDIT; the bottom rows will also have buttons
image

1 Like

Can anything be done so a new build will be available on https://blender.community/c/graphicall/ ?

1 Like

It is here Daily builds, but it seems to be quite old, I just asked LazyDodo for help
EDIT: I messed up. There are compiler differences on windows that I did not notice (I use Linux). I need to setup windows machine, It will take me a day to fix
EDIT: I just commited fix, build should be available soon (I will keep an eye on it)

@tintwotin it is up!

Sorry that you had to spend valuable time on getting the builds up and running again. Thank you. I gave it a spin.

  • The header should properly be visible as the factory setting of the Scripting workspace.
  • I don’t know if the spacing of the python errors is something you also deal with?
    image
    Imo, should the empty lines be removed and the line height should be no different than the transform message above.
  • Tooltips are missing from the Reports and Logs buttons.
  • The Case Sensitive button, when selected it seems to be off - maybe it should be reversed?
  • How do I get the messages in the system console to be printed in the log when ex. generating proxies in the VSE?

    They’re “printf” texts.
  • The Info menu seems to be broken in your build?
1 Like

Meh, it had to me done eventually. Anyway, thanks for taking enough interest to download the build and provide feedback. Not many will do that :slight_smile:

You will find a couple of this paper cuts (defaults, versioning, UI). I consider them to be secondary, I am changing too much in code to set defaults just yet. I will deal with it eventually.

This is todo. I was changing quite a bit of drawing code this week. Drawing code is hard to tackle, so I am moving slowly.
It is spacing between the lines in general (every multi line information). Wrapped text is calculated differently.

Yep, it was reversed, but only when not using globbing. I commited fix today.

I just fixed it today.

You can not, they are outside of logging system. In theory I can redirect system console to UI, but I am not sure about implications (it will not be possible to filter such text for sure).
Currently you need to convert printf to CLOG_*, what is quite easy, see commit with global log for reference (althoug local logger is prefered).

1 Like

Thanks for tightening the python errors, however now the python console looks weird at start-up, is this related?
image

Auto scroll - doesn’t seems to work? Scroll to some else than the latest line, make an error in python(in the text editor) - it doesn’t scroll to that position with the error.
I’m not sure it should be a setting, but just the way it behaves.
If it should be a setting it needs to be moved into the View menu.
It also makes the buttons to the right invisible on a 1920x1080 screen:
image

Normally all View related options should be in the View menu, but maybe ask the UI team for guidelines in this case? Also, ask them about text buttons in headers are okay, when William was the UI maintainer, it wasn’t. Inverse match needs a better icon, imo.
Why does the Info menu change name, when it has the same entries in both Report and Log mode?
The Context menu is only for options to edit the selected elements. It seems to me that the stuff you put in there actually belongs in the View menu.

Maybe use the tooltip to explain how to use wildcard, for now it is unclear.

1 Like