Consistently use default_log_level

[vlasakm]

Commit message:

There are currently two calls of luaotfload.log.set_loglevel:

• The early one in luaotfload-init.lua that respects the free
  default_log_level variable.
• The configuration one from luaotfload-configuration.lua, that
  defaults to 0.

This commit makes both settings respect the free default_log_level
variable, thus allows disabling of logging without any configuration
files.

I know that this is a bit controversial, but it would be useful in OpTeX and the default_log_level was already used in the code. Although it probably is a remnant of something and it was not meant to be overriden from outside.

[zauguin]

Although it probably is a remnant of something and it was not meant to be overriden from outside.

I think it's not so much a remnant but a hack to allow debugging parts which are loaded very early, but it's still completely unsupported and has a way too generic name. We should probably rename it to something like luaotfload_early_log_level / luaotfload_early_debug / etc.

More relevant to the matter at hand, we could consider a more general system for adjusting configuration options at a very early stage, but adding a one-off for a specific setting which can already be changed after luaotfload is loaded seems not like a great plan.

it would be useful in OpTeX

Could you elaborate on that? Why does OpTeX need this?

[vlasakm]

Although it probably is a remnant of something and it was not meant to be overriden from outside.

I think it's not so much a remnant but a hack to allow debugging parts which are loaded very early, but it's still completely unsupported and has a way too generic name. We should probably rename it to something like luaotfload_early_log_level / luaotfload_early_debug / etc.

More relevant to the matter at hand, we could consider a more general system for adjusting configuration options at a very early stage, but adding a one-off for a specific setting which can already be changed after luaotfload is loaded seems not like a great plan.

I also though of that, having a way to somehow merge in order: user configuration file settings, (say) format config and the luaotfload defaults. But I started small.

it would be useful in OpTeX

Could you elaborate on that? Why does OpTeX need this?

Currently we are exploring ways to control/limit information emitted to the terminal/log. One of the motivations is to make important messages more visible.

[zauguin]

(say) format config

Couldn't that be done much better by providing format specific configuration files? The only issue I see there is that it would curently be overwritten by user configuration files, but we could adapt the loading to allow multiple configurations files.

[vlasakm]

If there was a possibility to have a separate config file for format specifics, that would solve the issue at hand. It would also allow hopefully future proof handling of configuration values coming from formats, apart from formats just messing with luaotfload's internals.

Although there is the drawback of searching for the file, loading it and parsing it. Also, having the configuration options in Lua right next to require("luaotfload") would be more clear for the format documentation.

While discussing configuration, I have a few hacks to make luaotfload work for my use case. Could we try discussing configuration options for them or changes in upstream luaotfload? Is this PR the right place?

[zauguin]

If there was a possibility to have a separate config file for format specifics, that would solve the issue at hand. It would also allow hopefully future proof handling of configuration values coming from formats, apart from formats just messing with luaotfload's internals.

Wouldn't placing a luaotfload.conf in a format specific already work for this?

Also, having the configuration options in Lua right next to require("luaotfload") would be more clear for the format documentation.

Well we have the opposite situation in luaotfload itself. Documenting luaotfload.conf with "you might have a preexisting configuration file with exactly the same format you can look into" is much nicer than "all these default values might get randomly changed to values you have to search for in your format documentation" ;)
I don't know how OpTeX handles inline documentation, but if you have a docstrip like system than you can document them next to each other even if they end up in different places.

While discussing configuration, I have a few hacks to make luaotfload work for my use case. Could we try discussing configuration options for them or changes in upstream luaotfload? Is this PR the right place?

Please create separate issues for that.

[zauguin]

@vlasakm Are you at TUG 2021?

[vlasakm]

If there was a possibility to have a separate config file for format specifics, that would solve the issue at hand. It would also allow hopefully future proof handling of configuration values coming from formats, apart from formats just messing with luaotfload's internals.

Wouldn't placing a luaotfload.conf in a format specific already work for this?

The default TeX Live configuration (for TeX and Lua files at least) says to look into a few format specific directories first (like tex/lualatex, tex/latex and tex/generic) and then to fall back to all files (tex//). For example:

kpse.set_program_name("lualatex")

print(kpse.find_file("luaotfload.conf", "tex"))

Outputs (at least on my machine):

/home/michal/src/texlive/texmf-dist/tex/optex/base/luaotfload.conf

And currently any user config would be priorited over a format one.

Also, having the configuration options in Lua right next to require("luaotfload") would be more clear for the format documentation.

Well we have the opposite situation in luaotfload itself. Documenting luaotfload.conf with "you might have a preexisting configuration file with exactly the same format you can look into" is much nicer than "all these default values might get randomly changed to values you have to search for in your format documentation" ;)

Yeah, this is probably the way to go.

[vlasakm]

@vlasakm Are you at TUG 2021?

Watching the stream on the side, looking forward for a few presentations (including yours). Not registered though.

[zauguin]

Currently we are exploring ways to control/limit information emitted to the terminal/log. One of the motivations is to make important messages more visible.

One remark about that: Currently luaotfload's default log level is set to 0 which is the lowest documented level. So if you want to limit it further, are you thinking about negative log levels? (While we don't actively prohibit that, it would suppress all log output including some error messages, so I would strongly recommend against it.)

If there are specific things you consider unimportant which are logged at level 0, I think it would be better to raise them here so that we can see how important they are an if they should be moved to higher levels.

[vlasakm]

Currently we are exploring ways to control/limit information emitted to the terminal/log. One of the motivations is to make important messages more visible.

One remark about that: Currently luaotfload's default log level is set to 0 which is the lowest documented level. So if you want to limit it further, are you thinking about negative log levels? (While we don't actively prohibit that, it would suppress all log output including some error messages, so I would strongly recommend against it.)

If there are specific things you consider unimportant which are logged at level 0, I think it would be better to raise them here so that we can see how important they are an if they should be moved to higher levels.

Yes, I was thinking about negative log levels. Significant part of my usual log file is made up of:

luaotfload: Lua based OpenType font support 3.18 <2021-05-21>
lualibs: ConTeXt Lua standard libraries. 2.74 <2021-05-20>
lualibs-extended: ConTeXt Lua libraries -- extended collection. 2.74 <2021-05-20>
luaotfload | conf : Root cache directory is "/home/michal/.cache/mmtex/luatex-cache/generic/names".
luaotfload | init : Loading fontloader "fontloader-2021-05-20.lua" from kpse-resolved path "/usr/share/mmtex/tex/luaotfload/fontloader-2021-05-20.lua".
luaotfload | init : Context OpenType loader version 3.116
luaotfload | conf : Root cache directory is "/home/michal/.cache/mmtex/luatex-cache/generic/names".
luaotfload | db : Font names database loaded from /home/michal/.cache/mmtex/luatex-cache/generic/names/luaotfload-names.luc

(I omitted the attribute allocations, which are logged not handled by luaotfload)

If I am not really debugging luaotfload issues, I don't particularly need any of this information. And if I did, then I could just increase the log level. Hopefully, most encountered issues would be solved by seeing that the used version is too old :). If your experience is that user reports would be better with this information, then its fine, but I imagine, that user reports could benefit from more logging anyways, not just this level.

Note that this is necessarily not that bad, but I value short logs - the shorter it is, the more thought I give into each line. This is why for example I noticed #177, I presume it was like that for a while, and it caught my eye only because it is one of the few lines in my logs.

Perhaps it is just my attitutude, somewhat coming from the Unix philosophy "programs should stay silent, unless they have something important to say" and "if a program should fail, it should be early and loudly". Both principles are not really prevalent in the TeX community, which speaks against them, though.

EDIT:

I understand, that fitting luaotfload's and ConTeXt's logging together is hard, and distinguishing real errors that should be reported is even harder, but ideally real errors would not be influenced by log level. Again possibly only my opinion.

While I would like to see this change land, for its simplicity and consistency, I wouldn't want you to put time into serving this unusual use case if it would require more significant effor than this pull request.

[zauguin]

Perhaps it is just my attitutude, somewhat coming from the Unix philosophy "programs should stay silent, unless they have something important to say" and "if a program should fail, it should be early and loudly".

Personally I think that it really depends on where something is written to. So e.g. I would agree completely with "programs should stay silent, unless they have something important to say" when it comes to stdout or stderr, but IMO the logfile is a bit different since it's specifically made for additional information. When I'm opening the logfile, that's a direct request to get a more detailed view of whats happening. (Of course there are limits to how much information we want there, it's a balance) Also there are sometimes things where it is (relatively) likely that when this information is needed, another run with more verbose settings does not reproduce the same issues and messages. This kind of stuff I believe belongs into the Log. Of cource YMMV.

Anyway, some direct remarks about the listed lines:

luaotfload: Lua based OpenType font support 3.18 <2021-05-21>

IMO this is important to have in the logfile since the luaotfload version can change between runs (so it's not enough to look into the format logs) and any bug report/feature request/remark is basically pointless if not even the version is known.

Anyway the logging isn't handled by luaotfload.

luaotfload | conf : Root cache directory is "/home/michal/.cache/mmtex/luatex-cache/generic/names".

Should probably only get printed at this level if no cache was found, otherwise it's redundant.

luaotfload | init : Loading fontloader "fontloader-2021-05-20.lua" from kpse-resolved path "/usr/share/mmtex/tex/luaotfload/fontloader-2021-05-20.lua".

The issue with the fontloader is that loading a different is basically like a version change and since it's selected in the configuration file which also sets the log level, increasing the log level will often switch to the default fontloader as a side effect. We could look into an approach like for the module version numbers here: Only log it if it's not the default.

luaotfload | init : Context OpenType loader version 3.116

I don't think that this should be printed by default.

luaotfload | conf : Root cache directory is "/home/michal/.cache/mmtex/luatex-cache/generic/names".

Duplication is always bad, but I think this instance makes more sense then the first one.

luaotfload | db : Font names database loaded from /home/michal/.cache/mmtex/luatex-cache/generic/names/luaotfload-names.luc

While not essential information by itself, it's rather useful for analyzing lookup issues and since every run tries to save a new cache this can easily change when rerunning the file, this can't reliably be retrieved by increasing the log level.

but ideally real errors would not be influenced by log level.

Well, we use log level 0 to indicate that something should be printed independent of the log level. That's the main cause of my concern: Not so much that I consider particular messages to be very important (I would be open to raise all levels by 1, including the default, and add a new very silent level 0), but that suppressing them by using negative log levels is relying basically on missing error checking and violates invariants we implicitly depend on.

[vlasakm]

Perhaps it is just my attitutude, somewhat coming from the Unix philosophy "programs should stay silent, unless they have something important to say" and "if a program should fail, it should be early and loudly".

Personally I think that it really depends on where something is written to. So e.g. I would agree completely with "programs should stay silent, unless they have something important to say" when it comes to stdout or stderr, but IMO the logfile is a bit different since it's specifically made for additional information. When I'm opening the logfile, that's a direct request to get a more detailed view of whats happening. (Of course there are limits to how much information we want there, it's a balance) Also there are sometimes things where it is (relatively) likely that when this information is needed, another run with more verbose settings does not reproduce the same issues and messages. This kind of stuff I believe belongs into the Log. Of cource YMMV.

Agreed.

luaotfload: Lua based OpenType font support 3.18 <2021-05-21>

IMO this is important to have in the logfile since the luaotfload version can change between runs (so it's not enough to look into the format logs) and any bug report/feature request/remark is basically pointless if not even the version is known.

Agreed

luaotfload | conf : Root cache directory is "/home/michal/.cache/mmtex/luatex-cache/generic/names".

Should probably only get printed at this level if no cache was found, otherwise it's redundant.

This would be nice.

luaotfload | init : Loading fontloader "fontloader-2021-05-20.lua" from kpse-resolved path "/usr/share/mmtex/tex/luaotfload/fontloader-2021-05-20.lua".

The issue with the fontloader is that loading a different is basically like a version change and since it's selected in the configuration file which also sets the log level, increasing the log level will often switch to the default fontloader as a side effect. We could look into an approach like for the module version numbers here: Only log it if it's not the default.

Log if not default is nice for this.

luaotfload | init : Context OpenType loader version 3.116

I don't think that this should be printed by default.

At first I though the same, becuase it is tied to luaotfload. This may be connected to the above. But maybe this one has value, because of the different font loaders (although except for development I am not sure of the usefulness of the different font loaders concept, when it is just different versison of the ConTeXt code, mismatching versions are recipe for trouble for normal users anyways)

luaotfload | db : Font names database loaded from /home/michal/.cache/mmtex/luatex-cache/generic/names/luaotfload-names.luc

While not essential information by itself, it's rather useful for analyzing lookup issues and since every run tries to save a new cache this can easily change when rerunning the file, this can't reliably be retrieved by increasing the log level.

OK.

but ideally real errors would not be influenced by log level.

Well, we use log level 0 to indicate that something should be printed independent of the log level. That's the main cause of my concern: Not so much that I consider particular messages to be very important (I would be open to raise all levels by 1, including the default, and add a new very silent level 0), but that suppressing them by using negative log levels is relying basically on missing error checking and violates invariants we implicitly depend on.

I understand. Please don't go out of your way for this.