Problem with defined function in templates

[Terisa de morgan]

Hello,

I think I've already had this problem but I don't remember where to look at for solving it.

I've got some functions defined in bbdd to use in templates. However, they don't appear now when I query the defined functions, only the standard ones appear. The debug log shows the following information (obt_lei is one of my functions):

Spoiler:

Traceback (most recent call last):
File "calibre\utils\formatter.py", line 1966, in safe_format
File "calibre\utils\formatter.py", line 1844, in evaluate
File "calibre\utils\formatter.py", line 1684, in _eval_program
File "calibre\utils\formatter.py", line 460, in program
File "calibre\utils\formatter.py", line 473, in expression_list
File "calibre\utils\formatter.py", line 614, in top_expr
File "calibre\utils\formatter.py", line 617, in or_expr
File "calibre\utils\formatter.py", line 625, in and_expr
File "calibre\utils\formatter.py", line 636, in not_expr
File "calibre\utils\formatter.py", line 639, in string_binary_expr
File "calibre\utils\formatter.py", line 647, in compare_expr
File "calibre\utils\formatter.py", line 658, in add_subtract_expr
File "calibre\utils\formatter.py", line 666, in times_divide_expr
File "calibre\utils\formatter.py", line 680, in unary_plus_minus_expr
File "calibre\utils\formatter.py", line 767, in expr
File "calibre\utils\formatter.py", line 473, in expression_list
File "calibre\utils\formatter.py", line 614, in top_expr
File "calibre\utils\formatter.py", line 617, in or_expr
File "calibre\utils\formatter.py", line 625, in and_expr
File "calibre\utils\formatter.py", line 636, in not_expr
File "calibre\utils\formatter.py", line 639, in string_binary_expr
File "calibre\utils\formatter.py", line 647, in compare_expr
File "calibre\utils\formatter.py", line 658, in add_subtract_expr
File "calibre\utils\formatter.py", line 666, in times_divide_expr
File "calibre\utils\formatter.py", line 680, in unary_plus_minus_expr
File "calibre\utils\formatter.py", line 760, in expr
File "calibre\utils\formatter.py", line 358, in error
ValueError: Formatter: Función desconocida obt_lei cerca de 'obt_lei' en la línea 2

Where can I check to try to debug the error?

Thanks in advance.

[chaley]

It seems that the user defined functions have disappeared. I don't know why. There haven't been any changes to stored templates and functions for a long time.

You can check if they are still in the DB by looking in metadata_db_prefs_backup.json for the key "user_template_functions", or directly in the database in the preferences table. If the functions are there then I will need the metadata.db to debug why they aren't being loaded.

If they are not there then you must think about what might have happened. I can imagine a database restore losing the functions. You can probably put them back by editing the preferences table and adding that key from a backup.

[Terisa de morgan]

Both entries (metadata_db_prefs_backup.json and metadata.db) are present. And it doesn't happen only at one library, it happens at least at two of them.

[chaley]

In which case I need a sample database where loading the functions fails. The database must include the functions and at least one book entry that uses the functions. You can send me the entire metadata.db (zipped) if you don't mind me seeing what is in it.

Send it to me at calibre_bugs at charleshaley dot org. I don't need any books.

I wish MobileRead supported sending attachments via private message.

[Terisa de morgan]

I totally agree about private messages. File sent.

[chaley]

Got the db, thanks.

Problem: it works for me on Windows 10 Pro, calibre 7.2 standard (not from source), minimal configuration (no plugins). It also works from source. It also works with my test library configuration that has a zillion plugins.

This screen capture shows what I see when I open the template tester on a book.


This capture shows the template tester calling one of your functions:


Are you seeing the problem when using the template tester? Or when you are defining a template for some other purpose such as a column rule or a composite column? When opening a library, or when switching to that library?

[Terisa de morgan]

I'm attaching what I see in Spanish at the template tester. As you see, the functions are not present and, if I try to use it, it fails. I've tested only with template tester, and problem exists both when I open the library or change to a library.
When I create a composite column, as there is no help, no list, but I can use the function and, later, it works.

[chaley]

As I said, I can't make it fail, either when using the template tester on a book or when defining a composite column. (Note: when defining a new column you can right-click on the template box to open a template editor.)

I wonder if it has something to do with a plugin. Could you zip your calibre config folder and send it to me so I can run a test with the same plugins and settings that you have? I know that Action Chains does things with template functions. Do you have any chains that run at startup? You could try running calibre with

calibre --ignore-plugins

to see if the behavior changes.

Another test would be for you to open the library with a clean (empty) configuration folder. What I did was copy the config folder somewhere then emptied the original. When I started calibre I got the startup wizard, where I picked the library containing your metadata.db. This process removes all plugins and all settings.

If you can run from source then we might learn something from adding a debugging print to the template tester. The two lines of code are:

        print(f'Using standard builtin and custom functions: {all_functions is None}')
        traceback.print_stack()

In current source and almost certainly source for 7.2 they go at line 411, as shown here.

[Terisa de morgan]

The problem is a plugin, yes. Executing calibre --ignore-plugins means that the template tester finds the functions (BTW, the template editor from the column definition has the same behavior). I'm going to try to see if I remember how to run calibre from source (I did it long time ago and my memory is quite volatile if I do a thing only once).

[chaley]

Originally Posted by Terisa de morgan

I'm going to try to see if I remember how to run calibre from source (I did it long time ago and my memory is quite volatile if I do a thing only once).

If I do something one time then I am lucky to remember that I ever did it, much less how I did it.

[Terisa de morgan]

I thinkI've done something wrong because this is the log:

Spoiler:

File "runpy.py", line 198, in _run_module_as_main
File "runpy.py", line 88, in _run_code
File "site.py", line 95, in <module>
File "site.py", line 90, in main
File "site.py", line 50, in run_entry_point
File "C:\git\calibre\src\calibre\debug.py", line 233, in main
File "C:\git\calibre\src\calibre\debug.py", line 189, in run_debug_gui
File "C:\git\calibre\src\calibre\gui_launch.py", line 73, in calibre
File "C:\git\calibre\src\calibre\gui2\main.py", line 552, in main
File "C:\git\calibre\src\calibre\gui2\main.py", line 564, in run_main
File "C:\git\calibre\src\calibre\gui2\main.py", line 402, in run_gui
File "C:\git\calibre\src\calibre\gui2\main.py", line 418, in run_gui_
File "C:\git\calibre\src\calibre\gui2\actions\show_temp late_tester.py", line 67, in show_template_editor
File "C:\git\calibre\src\calibre\gui2\dialogs\template_ dialog.py", line 412, in __init__

[chaley]

Originally Posted by Terisa de morgan

I thinkI've done something wrong because this is the log:

Spoiler:

File "runpy.py", line 198, in _run_module_as_main
File "runpy.py", line 88, in _run_code
File "site.py", line 95, in <module>
File "site.py", line 90, in main
File "site.py", line 50, in run_entry_point
File "C:\git\calibre\src\calibre\debug.py", line 233, in main
File "C:\git\calibre\src\calibre\debug.py", line 189, in run_debug_gui
File "C:\git\calibre\src\calibre\gui_launch.py", line 73, in calibre
File "C:\git\calibre\src\calibre\gui2\main.py", line 552, in main
File "C:\git\calibre\src\calibre\gui2\main.py", line 564, in run_main
File "C:\git\calibre\src\calibre\gui2\main.py", line 402, in run_gui
File "C:\git\calibre\src\calibre\gui2\main.py", line 418, in run_gui_
File "C:\git\calibre\src\calibre\gui2\actions\show_temp late_tester.py", line 67, in show_template_editor
File "C:\git\calibre\src\calibre\gui2\dialogs\template_ dialog.py", line 412, in __init__

The results of the print are missing. Did you run calibre with

calibre-debug -g

?

The goal is to see whether something is calling the template tester with its own functions. It may end up showing us nothing, in which case I will need to put the print statements elsewhere.

[Terisa de morgan]

This is the result with print:

Spoiler:

Using standard builtin and custom functions: True
File "runpy.py", line 198, in _run_module_as_main
File "runpy.py", line 88, in _run_code
File "site.py", line 95, in <module>
File "site.py", line 90, in main
File "site.py", line 50, in run_entry_point
File "C:\git\calibre\src\calibre\debug.py", line 231, in main
File "C:\git\calibre\src\calibre\gui_launch.py", line 73, in calibre
File "C:\git\calibre\src\calibre\gui2\main.py", line 552, in main
File "C:\git\calibre\src\calibre\gui2\main.py", line 564, in run_main
File "C:\git\calibre\src\calibre\gui2\main.py", line 402, in run_gui
File "C:\git\calibre\src\calibre\gui2\main.py", line 418, in run_gui_
File "C:\git\calibre\src\calibre\gui2\actions\show_temp late_tester.py", line 67, in show_template_editor
File "C:\git\calibre\src\calibre\gui2\dialogs\template_ dialog.py", line 413, in __init__

tracestack is failing.

[Terisa de morgan]

User templates are lost after "Save Composite Columns" plugin is executed and Action Chains/Editor Chains are initialized.

After putting the print.tracestack at other place, I've found this:

Spoiler:

File "C:\git\calibre\src\calibre\debug.py", line 231, in main
File "C:\git\calibre\src\calibre\gui_launch.py", line 73, in calibre
File "C:\git\calibre\src\calibre\gui2\main.py", line 552, in main
File "C:\git\calibre\src\calibre\gui2\main.py", line 564, in run_main
File "C:\git\calibre\src\calibre\gui2\main.py", line 402, in run_gui
File "C:\git\calibre\src\calibre\gui2\main.py", line 418, in run_gui_
File "C:\git\calibre\src\calibre\gui2\main.py", line 376, in initialize
File "C:\git\calibre\src\calibre\gui2\main.py", line 355, in initialize_db
File "C:\git\calibre\src\calibre\gui2\main.py", line 312, in initialize_db_stage2
File "C:\git\calibre\src\calibre\gui2\main.py", line 260, in start_gui
File "C:\git\calibre\src\calibre\gui2\ui.py", line 446, in post_initialize_actions
File "C:\git\calibre\src\calibre\db\cache.py", line 2798, in __del__
File "C:\git\calibre\src\calibre\db\cache.py", line 2836, in close
File "C:\git\calibre\src\calibre\db\backend.py", line 1363, in close
File "C:\git\calibre\src\calibre\utils\formatter_functi ons.py", line 2764, in unload_user_template_functions
File "C:\git\calibre\src\calibre\utils\formatter_functi ons.py", line 109, in unregister_functions
File "C:\git\calibre\src\calibre\utils\formatter_functi ons.py", line 102, in _register_functions

At this point, library functions disappear. Checking backend.py, I can see this:

Spoiler:

def close(self, force=False, unload_formatter_functions=True):
if getattr(self, '_conn', None) is not None:
if self.prefs['expire_old_trash_after'] == 0:
self.expire_old_trash(0)
if unload_formatter_functions:
try:
unload_user_template_functions(self.library_id)
except Exception:
pass
self._conn.close(force)
del self._conn
self.is_closed = True

So, no plugin is responsible. I'm thinking this code is not called if there is no plugin, and that's the reason that it works in that case.

Well, knowing this, at least I know where to look for the functions.

[chaley]

Thank you for taking the time to continue tracing this.

What those traces say is that python garbage collection is collecting (deleting) the current database, thus closing it or a copy of it.

In other words, I think that something is opening the database of the current library or creating a copy (copy.deepcopy()) of an open instance variable, saving it as a local variable. When GC (garbage collection) is called that local copy is closed. There are timing problems here. The local variable might not be collected in some situations.

The only way I can see to verify this is to remove the plugins one at a time to see if the problem goes away. I would start with Action Chains, as I checked SaveCompositeColumns and it doesn't reopen or make a copy of the DB. If the plugin is found then we can look for why the variable that GC collects is created.

I hope Kovid notices this thread. He will probably have ideas on why it is happening and how to find it.