User:Grzelins/GSoC2020/ProjectDetails

=Technical details and study of GSoC info editor improvements=

Right now this document serves as notes for me, I am constantly updating it.

Info editor - current status

 * info editor operated directly on `ReportList` from `wmWindowManager`
 * drawing rows (`textview_draw`) is shared with `space_console`
 * there is some code left over from 2.79 which seems to no longer belong to this directory (like `pack_libraries_exec`)
 * keymap is set in `def km_info(params)`

Logs - current status
Log is fine detail info visible only in console, to change log settings you need to start blender with appropriate `--log*` flag. Many files creates logger locally ex. `static CLG_LogRef LOG = {"ed.undo"};`. `CLG_LogRef` is only reference, memory is owned by `CLogContext` and stored in `CLG_LogType`. Simplifying, there is one logger "type" wrapped in several functions and macros which ends with `puts` function. Logging function takes log as string - this string is already formatted.

Logging macros (CLOG) enforce text structure:  (): : : 

Example:

INFO (wm.msgbus.sub): /home/mat/blender-sources/blender-src/source/blender/windowmanager/message_bus/intern/wm_message_bus_rna.c:292 WM_msg_subscribe_rna_params: rna(id=' ', Object.mode, info='view3d_main_region_message_subscribe')

There are around 420 `CLOG` entries in code (`grep -r CLOG | wc -l`).

if (clg_ctx_filter_check(ctx, ty->identifier)) { ty->flag |= CLG_FLAG_USE; }
 * each logger has id `static CLG_LogRef LOG = {"bke.action"};`
 * log filtering is very basic (`clg_ctx_filter_check`)
 * `CLG_LogRef` is initialized with `CLOG_ENSURE` (which calls `CLG_logref_init`) - every time you use `CLOG_INFO` there is optional call to `CLOG_ENSURE`
 * `CLogContext` store pointer to `FILE` thus can be dumped to disk
 * logs are not saved in memory: immediately after print, message string is destroyed
 * todo how is log enabled/disabled on the fly?
 * calling `CLG_type_filter_exclude`, `CLG_type_filter_include` from `arg_handle_log_set` affects fied `CLG_IDFilter *filters[2];`
 * information from filters is used to set flag in `CLG_LogType`

Logs from depsgraph

 * most prints are done in `DEG_debug_print_*` and in macro like `DEG*_DEBUG_PRINTF` but there are also multiple prints all across code
 * debug graphs are drawn with gnuplot and/or graphviz (`blender\source\blender\depsgraph\DEG_depsgraph_debug.h`)

Logs from third party libraries
todo investigate: namespace Freestyle { // XXX Grmll... G is used as template's typename parameter :/ static const Global &_global = G;
 * GPU `gpu_debug_init`
 * ffmpeg
 * XR `GHOST_kXrContextDebug`
 * what is going on with freestyle?? `blender\source\blender\freestyle\intern\view_map\ViewMapBuilder.cpp`
 * 1) define LOGGING 0
 * `blender\source\blender\imbuf\intern\cineon\logImageCore.c`?

Debug - current status
Debug is flag which is set in global structure `G`. We have ~20 `G_DEBUG*` flags.

Typical usage for debugs: if (G.debug & G_DEBUG) { printf("Error: No active view for painting\n"); }

It is common to see file-wide mini debug macro like: if (AVI_DEBUG) { \ printf("AVI DEBUG: " x); \ } (void)0
 * 1) define DEBUG_PRINT(x) \

Some debug is defined only in debug builds or specific flags enabled: void BLF_state_print(int fontid)
 * 1) ifdef DEBUG
 * 1) endif

but sometimes it is wrapped in both define and if: if (_global.debug & G_DEBUG_FREESTYLE) { cout << "something"; }
 * 1) if LOGGING
 * 1) endif


 * do we want to have some kind of convention for debugging? Every `if (G.debug)` is small performance penalty, so maybe have it always wrapped in `#if`?
 * todo what is going on with macro `NDEBUG`?

Reports - current status

 * reports (`Report`, `ReportList`) are part of `wmWindowManager`
 * because reports are part of window manager they can be displayed immediately
 * report interface is created by `uiTemplateReportsBanner`, `UI_popup_menu_reports` (actual popup menu)
 * `Report` has `ReportType` (enum like `RPT_DEBUG`, `RPT_PROPERTY` ...)
 * `Report` has flag `ReportListFlags` ( enum like `RPT_PRINT`, `RPT_STORE` ...)
 * `ReportTimerInfo` controls reports display time
 * `ReportList` is used in multiple places: curves, mesh, ffmpeg, gpencil, everywhere where user needs to see message right now
 * report can be displayed in info editor
 * info editor listens for new reports in `info_main_region_listener` (listens for specific event in `wmNotifier`) and redraws region
 * when blender runs in background reports are printed to stdout, see `BKE_report`

Example usages: BKE_reportf(reports, RPT_ERROR, "KeyConfig '%s' cannot be removed", keyconf->idname); BKE_reportf(reports, RPT_ERROR, "KeyConfig '%s' cannot be removed", keyconf->idname); BKE_reportf(data->reports, RPT_WARNING, "Path '%s' cannot be made absolute", path_src);

Some usages of report look a bit like log: BKE_reportf(op->reports, RPT_INFO, "Copied %d selected object(s)", num_copied); BKE_reportf(op->reports, RPT_ERROR, "Parse error in %s", __func__);

Python API - current status

 * `bpy.app.debug*` exposes 17 flags from `G.debug`, some are missing
 * it seems it is not possible to assign button to `bpy.app.debug` from python script. todo how to implement it?
 * should it be converted to RNA bool property?
 * todo investigate how ui menu debug_value is implemented - `wm_debug_menu_exec`
 * todo investigate `p` function in `blender\release\scripts\addons\blenderkit\utils.py`

Python error reporting

 * python is evaluated in `BPY_execute_text`
 * evaluating from text editor:
 * syntax error are shown in info editor (although not great), but not execution errors. The difference is that syntax errors are reported during compilation in `python_script_exec`
 * the real question is how to capture error from `PyEval_EvalCode` https://stackoverflow.com/questions/4307187/how-to-catch-python-stdout-in-c-code

CLI - current status
Logging Options: --log --log-level --log-show-basename --log-show-backtrace --log-show-timestamp --log-file Debug Options: -d or --debug --debug-value Set debug value of on startup. --debug-* ...   --debug-all --disable-crash-handler --disable-abort-handler ...   --verbose


 * todo what is the difference verbose vs log-level?
 * todo how will be CLI impacted?

Misc questions/issues

 * todo what is replay system? T68656
 * is `BLI_assert` meant to crash blender, or is it log-able?
 * what does `ATTR_PRINTF_FORMAT` do?
 * it seems that blender show in ui exactly what is in the structure when it comes to info editor. Is there some kind of view layer in blender at all?
 * inaccuracy of info editor: (ex T61525)
 * when switching for ex. between object mode and edit mode tooltip:
 * tooltip shows: `bpy.ops.object.mode_set(mode='EDIT')`
 * info edit shows: `bpy.ops.object.editmode_toggle`
 * reasons?
 * is this pattern or edgecase?
 * left right arrow, space is active shortcut in info editor, I don't think this is desirable
 * if logger is not initialized, weird things happen with verbiosity (it is not initialized?), todo check `CLOG_CHECK` in `ed_undo.c:114`. It can be run only when both loggers are enabled what is counter intuitive: `blender --debug --log-level -2 --log "ed.undo,bke.undosys" --verbose 2`

Features/tasks/ideas/requirements
T68448 - parent task

UI

 * filter: a checkbox for each G.debug flag (24 checkboxes? ouch)
 * filter: a checkbox for each log type (42+ checkboxes? many more will appear as I convert prints to logs. ouch)
 * filter: log level (type): info, error..., P1320
 * filter: show only logs, that can be executed in python console (usefull for addons, nice to have)
 * search for log type (ex. `*undo*`)
 * search for logged text
 * log: use timestamp - should it be part of report by default?
 * log: use basename
 * set max log size (memory footprint) in preferences
 * how to incorporate this design with presets (that blender will implement in future)?
 * is it possible to expose graphs are drawn with gnuplot and/or graphviz as button?
 * select log file
 * highlight found text
 * if blender is not build with FFMPEG, do not show G_DEBUG_FFMPEG in indo editor. Is it hard to implement?
 * should we take into consideration option Developer extras from preferences?

Other

 * show python evaluation logs in info editor
 * we want logs to appear in console for server usage (`--background`). Do we want to make feature to disable console logging and display logs only in info editor?
 * we want to be sure that logs print to console before blender crashes
 * for server usage: do not store reports (logs at all), just print it to save memory
 * log output python console and executed scripts from text editor to info editor
 * manage memory required by logs, as memory usage will grow fast
 * add operator that will print blender version, commit etc. as `Report`
 * store log filers per space - if 2 info editors are open, you should be able to set different filters


 * file `blender\source\blender\editors\space_info\info_ops.c` (and related) should probably no longer be in info editor as it has been separated in 2.8. Where should it go?


 * should debug settings be saved with blend file?
 * expose blender log in python API as handler for python's built in logging module
 * expose freestyle debugging in build system?
 * `CLOG` is plain C. Will it work out of the box in cpp?
 * some parts of blender can be build separately. How will it affect log system?
 * do we want to support multiple log files? Ex one per info editor?
 * Industry compat keymap: change selection pattern in info editor to be consistent with outliner
 * are we able to show even more information in info editor?
 * ex. user paints with weight paint brush -> info editor show affected points in python syntax
 * ex. user moves vertex in edit mode -> info editor shows python operator for moving vertexs
 * show code responsible for setting user hotkeys
 * super usefull for reproducing bugs and developing addons
 * it is basically encoding user behaviour into executable python
 * missing in the Text Editor is that all error messages isn't written in the Info Editor or the Python Console

Outside of scope of this project

 * real time log watching:
 * logs that can be drawed on graph inside blender `blender\source\blender\depsgraph\intern\debug\deg_debug_stats_gnuplot.cc`
 * values that can be observed like mouse movement, jobs performance
 * separate logs from different threads?
 * pretty print logs:
 * extend `Report` struct to contain flag about formatting, ex. `char format`=PLAIN_TEXT or `PYTHON` or `LOGS`
 * todo investigate what Harleya has done in the past
 * todo: for drawing: how can we implement child rows ?
 * python console can also have pretty print enabled
 * syntax highlighting for logs? can be reused from `text_format.c`, we can change drawing engine to use `TextLine`
 * just an idea: if report comes from operator, can we show in which menu is the button? like search operation (under F3) shows path to menu

Proposed changes
There is geat ammount of monkey work that can be done, namely converting blender prints to logs.

Personally I get the feeling like this whole report system is only fancy log system. It makes less and less sense to keep those systems separated. (we have 850 usages of `BKE_report(` and 430 usages of `BKE_reportf(`). But it may be just too much work (?).

Display log in info editor
Basic idea is to allow `CLOG` make some kind of reports. Green arrow in the image represent connection to implement.

Note that memory management becomes a must.

Idea 1 extend `Report` structure to cover additional information coming from log system:
 * we should extend `enum ReportType` to cover log types coming from log system
 * todo is `ReportList` good enough for text search?

Idea 2 Introduce new `LogReport` type, use the same drawing engine to draw it

Pros Cons
 * flexibility
 * better to reuse and change what is already written

Idea 3 let info editor store new instance of `CLogContext`.

Pros:
 * in the current state, `CLogContext` has:
 * one file to write
 * filters

Cons:
 * we do not have system in place to handle multiple instances of `CLogContext`:
 * we probably want to share list of types in some way (one call to `CLG_INFO` writes to every context?)

Expose log to python API
We can make one `CLogContext` instance especially for addons: addon can register new logger type what will make it possible to display in info editor. This log should probably be only a handler for python's built in `logging` module.

todo make a concrete API here

Info Editor
This is first iteration, it is a too technical for proper UI mocap, but it helps to organise my thoughts

Preferences
Add field "Memory Log limit" to System -> Memory & Limits Add field "Log file path" to File Paths -> Development?
 * todo log path can be overriden from command line it would conflict with this preference setting