Add debugf function

[cmahnke]

See https://discourse.gohugo.io/t/add-debugf-function/45625

It would be very convenient to have a debugf function, where the output isn’t cached like errorf or warnf, but it would still be highlighted like their output. Debug output would be suppressed unless the -v verbose flag is given. Output would be prefixed by template filename and line if possible.

[jmooring]

What is the motivation behind this?

To clarify:

• The errorf and warnf functions do not "cache" output. Duplicate messages are not printed to avoid flooding the log. Use the math.Counter function to make messages unique. For example:

  {{ warnf "something [%d]" math.Counter }}
  

• The --verbose flag is deprecated and will be removed in a future release. Use --logLevel debug|info|warn|error instead.

Related: #10725

[cmahnke]

Actually the motivation would be better debugging infrastructure for Hugo themes. While it is true that it's possible to get rid of the "anti log flooding behaviour", there are certain situations where it is just counter intuitive and thus annoying.
I won't even try to open the can of worms suggesting an evaluation if the current behaviour is justified (my guess : users don't care for their logs, theme developers are annoyed).

Anyways, as you've mentioned the logLevels: There is currently no way to set a level with warnf, adding a debugf message would automatically imply debug, additionally it would disable the uniqueness check. Giving more info about the execution (not Hugo) context would be nice: Like printing template and processed file name - but that is, as you've pointed out, part of a function in another merge request.
I don't think that we would need a function infof to be consistent with the log levels.

This short table illustrates the idea further:

Function	logLevel	Behaviour	Terminal text color
debugf	debug	Prints every passed line (with source file name as prefix)	blue
not implemented	info	Reseverd for Hugo internal use, like deprecations etc.	green
warnf	warn	Filters duplicates	yellow / orange
errorf	error	Fails the build	red

Notes

• Text in brackets is optional
• Target audiences could be added to the table

And by the way: Having a debugf function would be the best way against long logs, since theme developers won't be forced to (ab-)use the warnf function anymore. Any message not intended for the end user just won't be displayed if the logLevel isn't explicitly set to debug.

[jmooring]

I am in favor of doing this; need bep's approval before proceeding.

Over the past week I've added math.Counter to warnf a few times to prevent duplicate messages from being muted. Using debugf would be convenient.

[bep]

So, I kind of want this myself (I'm using warnf for this ...), but the reasons I'm hesitating is:

• debug statements left during development have a tendency to be left there.
• As a user of that theme, it will clutter up the debug output that I want to see.
• It will also hurt performance if put in hot paths and/or is expensive to evaluate.

Also, having a console based debug tool that has no easy connection to where it gets logged (which template for which page`?) is not very useful.

I suspect what we're looking for is is something else, but I'm not totally sure what.

[bep]

Would adding a hugo.IsDebug function be useful for this, e.g.:

{{ if hugo.IsDebug }}
// Print some debug information somewhere on the HTML page or something.
{{ end }}

[cmahnke]

@bep:

• You're right, debug statements tend to stay, but from my point of view, this is by design / purpose.
• I would argue, that a user who requests debug level output can expect a cluttered output, since normal users aren't the implied taget audience for debug. My table was incomplete on this part: I would say that the different levels have different primary target audiences (warn for users, debug for theme developers etc.) and if anyone outside of those audiences requests a different level, it isn't expected to be helpful for that person.
• The last one is important, for me it doesn't really matter, so I don't have a strong opinion on this. It's certaily a bit ugly to pass arguments as literal (or do some other sort of lazy evaluation of them) so they can be evaluated after the check for the level is done.

And don't underestimate (feature) greedy developers, I won't mind:

{{ if hugo.IsDebug }}
   {{ debugf "This a guarded debug statement" }}
{{ end }}

[bep]

You're right, debug/trace statements tend to stay, but from my point of view, this is by design / purpose.

In my head there are 2 distinctive kinds of debug problems:

1. To help debug common recurring problems (e.g. the log output from Hugo's "cache buster")
2. To help solve problems with some particular code block during development.

Having the number 2s left after you've solved a particular problem is, in my head, never a great idea. It will make future troubleshooting accumulatively harder to do over time, and this gets especially annoying when you inherit debug statements from other developer (e.g. theme/modules).

[cmahnke]

I totally agree with that distinction but don't see a pragmatic solution: Logging frameworks usually solve this by adding just another level like trace, but this will make things more complicated, since it would add just another function (tracef) if the proposed model (one function for each log level) should still apply. Let alone more required test, documentation and other overhead.

Just for completeness to other readers: The used logging framework has trace.

Another approach would be be able to pass a level argument to debugf (or maybe logf), maybe as the first parameter, but since I'm not familiar with Go lang conventions, I'm not sure if this inconsistency (as compared to warnf, where the params are just the arguments for the supplied pattern) is acceptable.

[jmooring]

Going back to the beginning, it seems like the primary gripe with using warnf for debugging is that duplicate messages are muted. I have no problem doing this via a VS Code snippet...

{{ $v | warnf "%#[2]v [%[1]d]" math.Counter }}

...but I guess others do.

Maybe we could not mute duplicate warnings with --logLevel debug.

[cmahnke]

I'll try another approach in justifying the desire to have this. I'm aware that this isn't a strong argument:
With the upgrade to Version 0.123.0 the will be some breaking changes, these certainly need to be debugged.

From the discussion so far it is my understanding that we are at the crossroads of two paths:

• The original intent of this proposal: Adding a new function (which would be debugf) which enhances the current model of output methods and log levels (see above).
• Enhance the existing infrastructure (this is how I understood the arguments made by @bep and @jmooring), that would be basically just disable deduplication of messages --logLevel debug.

Since i'm the original reporter I'm certainly in favor of the first, but can definitely live with the second as well.

And while I'm at it, I would like to use the opportunity to stress the importance of good error messages. By "good" I mean that a error message should always state exactly what went wrong where (at least which template is "throwing", for which content file would be nice, as well as giving a hint how to fix things). Bad error messages in this sense are all that wouldn't give away any context at all.

• See "WARN .File.Lang on zero object. Wrap it in if or with: {{ with .File }}{{ .Lang }}{{ end }}"
• See "ERROR Failed to create content converter: no content renderer found for markup """

I'm not sure how much of these "bad" messages still exist in 0.123.0.

[bep]

Maybe we could not mute duplicate warnings with --logLevel debug.

We don't. If I remember correctly, we only de-duplicate from >= warning.

[jmooring]

I tested again with v0.123.0-DEV. Duplicate warning messages are muted regardless of logLevel. I added this to the docs a while back:

https://gohugo.io/functions/fmt/warnf/

[bep]

I tested again with v0.123.0-DEV. Duplicate warning messages are muted regardless of logLevel. I added this to the docs a while back:

I'm not sure I follow. Warning is a log level. We filter out duplicate log items of log level >= Warning. This has nothing to do with the --logLevel flag you set.

As to this issue: I still think that a debugf func for console debugging is a terrible idea, for several reasons. Adding console debug statements to your templates in a multithreaded build gets extremely confusing beyond the simplest of setups.

What I think we need to improve on is:

• Add some more debuggin context to the template context (e.g. the template stack)
• Add some debugging helpers to the template funcs so you can do {{ if hugo.IsDebug }}print some debugging info{{ end }}

Or something like that.

[jmooring]

I'm not sure I follow

I guess I was confused by this conversation:

Maybe we could not mute duplicate warnings with --logLevel debug.

We don't. If I remember correctly, we only de-duplicate from >= warning.

I'm fine with adding a counter, as shown above, to make warning messages unique.

[cmahnke]

Just to clear things up, my understanding of @jmooring 's proposal was, that there could be a logic witch would disable deduplication of a massage (of any level - the only viable candidate being warnf) if the --logLevel is set to debug (or even higher).

While I agree with @bep 's assesment about needed infrastructure, i tend to disagree on the partly patronizing point, which would be arguing with the multi treaded nature of the build process.
I think that most theme developers are coming from a background where a method to output some "stuff" (like console.log()), that isn't tempered (thats how I felt about deduplication, when I encountered it the first time(s)) with at all, is given. That the reason why they thing they need it in Hugo as well. It feels, to borrow your words:

extremely confusing beyond the simplest of setups

Because it's unexpected.

There still is some interest in having this function, by I guess it's there since people are extrapolating from the name of warnf and applying some "principle of symmetry" to just guess that the function would be one named debugf. Since I'm not a native speaker I hope you get what I'm trying to say with this...

Another (quite weak) idea regarding this proposal would be to integrate debugf as an alias to warnf or some sort of nop. That way there would be at least a reference in the docs which could hint towards the way, which is considered best practise. This might reduce the number of support requests on Discourse.

Back to the first comments: I get it, it's certainly not only about adding a function and I'm also guilty of broadening the scope:
This proposal is about one specific function (debugf) and I'm now some were between tempted and convinced to close it.

Since we certainly agree that the is much to be desired regarding debugging, I would open new ones, tightening the scope for each:

• An optional way to get rid of expectation defying deduplication (without the counter trick): That would be the proposal made by @jmooring
• Guarding by log level (hugo.IsDebug function) - @bep 's first point
• A guide line on minimal requirements on good error messages (see my comment above), but that's certainly one for hugoDocs. See also #7051 for a use case: Clickable line numbers and file names.
  That would feed into the next:
• Template stack - @bep 's second point, but as @jmooring already wrote, there is Add debug.ExecInfo.TemplateStack #10725 - so no need for a new one
• Maybe: debugf as an alias to warnf (see above) - but only if you want - I don't really care about this one

What do you think?

[simonheimlicher]

I really, really appreciate your considerations and the time you put into improving the debugging experience of Hugo for developers.

Maybe I can provide a real-world example of the contortions I am using in my templates to keep up your motivation to improve the debugging infrastructure of Hugo 😃

At the top of every template, I define the following preamble:

1. $template contains the name of the template
2. $dbg provides a prefix for debug messages, including the last two elements of its permalink path and the name of the template

{{- $template := "claris/_functions/resources/images/render-images" }}
{{- $dbg := printf "%s[%s]" (replaceRE `.*?((?:[^/]+/){,2})$` `$1` page.RelPermalink) (replaceRE `.*?([^/]+)$` `$1` $template) }}

To determine, which templates output debug messages, I use a number of approaches:

1. A per-template switch for debug messages in the form of a true|false statement
2. This is then ORed with for example an argument from the calling template (.Debug) or a page parameter (page.Param "clarisdebug"):

{{- $debug := and true (or .Debug (page.Param "clarisdebug") ) }}

Note that restricting the output to a single page helps keeping the output tractable in a multi-threaded application like Hugo.

For every single debug output, I need three lines:

{{- if $debug }}
  {{- warnf "%s Processing variant=%v with .version:\n%v" $dbg  $variantName (jsonify (dict "indent" "  ") $variantMeta.version) }}
{{- end }}

When the output gets too verbose, I disable some of those temporarily:

{{- if and false $debug }}
  {{- warnf "%s Processing imageMeta:\n%v" $dbg (jsonify (dict "indent" "  ") $imageMeta) }}
{{- end }}

I think there are a great number of ways Hugo could contribute to simplify the life of template developers such as myself.

A good start from my humble perspective would be the following:

1. Provide a function, e.g., debugf, which outputs an identifier for the current page and one for the current template or template stack.
2. Provide a per-site (i.e., per language if the page is multi-lingual) switch, a per-page switch and a per-template switch that turns this function into a no-op. I would prefer this as a convenient alternative for less performance-critical areas over the proposed hugo.IsDebug as it allows avoiding wrapping each debugf in an if clause.

This would turn the above code into just a debugf statement without any if clauses

{{- debugf "Processing variant=%v with .version:\n%v" $variantName (jsonify (dict "indent" "  ") $variantMeta.version) }}

To temporarily disable a debugf statement, one could simply comment it out as it would be only one line:

{{- /* {{- debugf "%s Processing imageMeta:\n%v" $dbg (jsonify (dict "indent" "  ") $imageMeta) }} */ -}}

[cmahnke]

@simonheimlicher Thanks for those suggestions, in my "kitchen sink"-theme I already do that partly (currently missing the page.RelPermalink part).
What you are actually are doing is to use the buildin methods to recreate functionalities provided in other languages by logging frameworks (like Python logging or Apache Log4j for Java)...
I think that this should be part of the core infrastructure. And it is my impression, that the maintainers have a similar view on the matter, but maybe not the time or a clear roadmap.

I'm well aware that there are ways to reach the proposed goal, but they aren't a integral part of the core infrastructure.

But providing your examples definitely helps in demonstrating that there is clear demand for improving the "tooling" of theme development.