Add Logging API

[lukastaegert]

This PR contains:

• bugfix
• feature
• refactor
• documentation
• other

Are tests included?

• yes (bugfixes and features will not be merged without tests)
• no

Breaking Changes?

• yes (breaking changes will not be merged unless absolutely necessary)
• no

List any relevant issue numbers:

• resolves RFC: Logging API #4981

Description

This implements a logging API as outlined in #4981. There are some differences from the outline that I want to highlight, though.

First, there is a new onLog input option, that receives three arguments: level, log and defaultHandler. The default handler is again called with two arguments level and log. If it is not called, the log is filtered, otherwise it is forwarded to onwarn if it is a warning and ultimately printed to the console. Here, level is either warn, info or debug. Errors are not passed through the Logging API, but logs can easily be turned into errors by calling the default handler with a level of error.

To filter logs by level, there is a new logLevel option that supports warn, info, debugorsilent`.

Plugins can generate logs by calling either this.warn, this.info, or this.debug. Using separate functions per log level allows us to keep object identities between the generated logs and what is passed to onLog while also allowing us to efficiently replace those functions with noop handlers depending on the log level.

Plugins have an onLog hook that can easily filter logs by returning false, or emit new/additional logs like any other hook.

The console logs generated by experimentalMinChunkSize and experimentalLogSideEffects are turned into proper info logs with the codes OPTIMIZE_CHUNK_STATUS and FIRST_SIDE_EFFECT.

Please see the documentation changes for additional information, feedback welcome! cc @patak-dev @sapphi-red @marvinhagemeister @yyx990803 @antfu

configuration options

logLevel

Type:	LogLevel | "silent"
CLI:	--logLevel <level>
Default:	"info"

Determine which logs to process. See onLog for the available log levels. The default logLevel of "info" means that info and warnings logs will be processed while debug logs will be swallowed, which means that they are neither passed to plugin onLog hooks nor the onLog option or printed to the console.

When using the CLI, errors will still be printed to the console as they are not processed via the logging system. See the --silent flag for how to suppress error logs.

onLog

Type:	(level: LogLevel, log: RollupLog, defaultHandler: LogOrStringHandler) => void;

type LogLevel = 'warn' | 'info' | 'debug';

type LogOrStringHandler = (
	level: LogLevel | 'error',
	log: string | RollupLog
) => void;

// All possible properties, actual properties depend on log
interface RollupLog {
	binding?: string;
	cause?: Error;
	code?: string;
	exporter?: string;
	frame?: string; // always printed by the CLI
	hook?: string;
	id?: string; // always printed by the CLI
	ids?: string[];
	loc?: {
		column: number;
		file?: string;
		line: number;
	}; // always printed by the CLI if id is present
	message: string; // the actual message, always printed by the CLI
	meta?: any; // add custom plugin properties to logs
	names?: string[];
	plugin?: string; // added by Rollup for plugin logs, only printed for warnings
	pluginCode?: string; // added by Rollup for plugin logs that contain a code
	pos?: number;
	reexporter?: string;
	stack?: string; // url for additional information, always printed by the CLI
	url?: string;
}

A function that intercepts log messages. If not supplied, logs are printed to the console, whereby Rollup CLI aggregates certain "warn" logs and prints consolidated warnings after the build to reduce noise. This handler is also triggered when using the --silent CLI option.

The function receives three arguments: the log level, the log object and the default handler. Log objects have, at a minimum, a code and a message property, allowing you to control how different kinds of logs are handled. Other properties are added depending on the type of log. See utils/logs.ts for a complete list of built-in errors and logs together with their codes and properties.

If the default handler is not invoked, the log will not be printed to the console. Moreover, you can change the log level by invoking the default handler with a different level. Using the additional level "error" will turn the log into a thrown error that has all properties of the log attached.

// rollup.config.js
export default {
	//...
	onLog(level, log, handler) {
		if (log.code === 'CIRCULAR_DEPENDENCY') {
			return; // Ignore circular dependency warnings
		}
		if (level === 'warn') {
			handler('error', log); // turn other warnings into errors
		} else {
			handler(level, info); // otherwise, just print the log
		}
	}
};

This handler will not be invoked if logs are filtered out by the logLevel option. I.e. by default, "debug" logs will be swallowed.

Some logs also have a loc property and a frame allowing you to locate the source of the log:

// rollup.config.js
export default {
	//...
	onLog(level, { loc, frame, message }) {
		if (loc) {
			console.warn(`${loc.file} (${loc.line}:${loc.column}) ${message}`);
			if (frame) console.warn(frame);
		} else {
			console.warn(message);
		}
	}
};

plugin development

onLog

Type:	(level: LogLevel, log: RollupLog) => boolean | null
Kind:	sync, sequential
Previous/Next:	This hook can be triggered at any time.

See the onLog option for the available Loglevel values and the RollupLog type.

A function that receives and filters logs and warnings generated by Rollup and plugins before they are passed to the onLog option or printed to the console.

If false is returned from this hook, the log will be filtered. Otherwise, the log will be handed to the onLog hook of the next plugin, the onLog option, or printed to the console. Plugins can also change the log level of a log or turn a log into an error by passing the log to this.error, this.warn, this.info or this.debug and returning false. Note that unlike other plugin hooks that add e.g. the plugin name to the log, those functions will not add or change properties of the log. Additionally, logs generated by an onLog hook will not be passed back to the onLog hook of the same plugin. If another plugin generates a log in response to such a log in its own onLog hook, this log will not be passed to the original onLog hook, either.

function plugin1() {
	return {
		name: 'plugin1',
		buildStart() {
			this.info({ message: 'Hey', pluginCode: 'SPECIAL_CODE' });
		},
		onLog(level, log) {
			if (log.plugin === 'plugin1' && log.pluginCode === 'SPECIAL_CODE') {
				// We turn logs into warnings based on their code. This warnings
				// will not be passed back to the same plugin to avoid an
				// infinite loop, but other plugins will still receive it.
				this.warn(log);
				return false;
			}
		}
	};
}

function plugin2() {
	return {
		name: 'plugin2',
		onLog(level, log) {
			if (log.plugin === 'plugin1' && log.pluginCode === 'SPECIAL_CODE') {
				// You can modify logs in this hooks as well
				log.meta = 'processed by plugin 2';
				// This turns the log back to "info". If this happens in
				// response to the first plugin, it will not be passed back to
				// either plugin to avoid an infinite loop. If both plugins are
				// active, the log will be an info log if the second plugin is
				// placed after the first one
				this.info(log);
				return false;
			}
		}
	};
}

Like the options hook, this hook does not have access to most plugin context utility functions as it may be run before Rollup is fully configured. The only supported properties are this.meta as well as this.error, this.warn, this.info and this.debug for logging and errors.

this.debug

Type:	(log: string | RollupLog | (() => RollupLog | string), position?: number | { column: number; line: number }) => void

Generate a "debug" log. See this.warn for details. Debug logs always get code: "PLUGIN_LOG" added by Rollup. Make sure to add a distinctive pluginCode to those logs for easy filtering.

These logs are only processed if the logLevel option is explicitly set to "debug", otherwise it does nothing. Therefore, it is encouraged to add helpful debug logs to plugins as that can help spot issues while they will be efficiently muted by default. If you need to do expensive computations to generate the log, make sure to use the function form so that these computations are only performed if the log is actually processed.

function plugin() {
	return {
		name: 'test',
		transform(code, id) {
			this.debug(
				() =>
					`transforming ${id},\n` +
					`module contains, ${code.split('\n').length} lines`
			);
		}
	};
}

this.info

Type:	(log: string | RollupLog | (() => RollupLog | string), position?: number | { column: number; line: number }) => void

Generate an "info" log. See this.warn for details. Info logs always get code: "PLUGIN_LOG" added by Rollup. As these logs are displayed by default, use them for information that is not a warning but makes sense to display to all users on every build.

If the logLevel option is set to "warn" or "silent", this method will do nothing.

this.warn

Type:	(log: string | RollupLog | (() => RollupLog | string), position?: number | { column: number; line: number }) => void

Using this method will generate warnings for a build, which are logs with log level "warn". See the onLog option for information about the RollupLog type. To generate other logs, see also this.info and this.debug. To generate errors, see this.error.

Just like internally generated warnings, these logs will be first passed to and filtered by plugin onLog hooks before they are forwarded to custom onLog or onwarn handlers or printed to the console.

The warning argument can be a string or an object with (at minimum) a message property:

this.warn('hmm...');
// is equivalent to
this.warn({
	message: 'hmm...',
	pluginCode: 'CODE_TO_IDENTIFY_LOG',
	meta: 'Additional plugin specific information'
});

We encourage you to use objects with a pluginCode property as that will allow users to easily filter for those logs in an onLog handler. If you need to add additional information, you can use the meta property. If the log contains a code and does not yet have a pluginCode property, it will be renamed to pluginCode as plugin warnings always get a code of PLUGIN_WARNING added by Rollup. To prevent this behavior, plugins can instead use the normalized onLog option passed to the buildStart hook. Calling this option from a plugin will not change properties when passing the log to plugin onLog handlers and onLog or onwarn handlers.

If you need to do expensive computations to generate a log, you can also pass a function returning either a string or a RollupLog object. This function will only be called if the log is not filtered by the logLevel option.

// This will only run if the logLevel is set to "debug"
this.debug(() => generateExpensiveDebugLog());

When used in the transform hook, the id of the current module will also be added and a position can be supplied. This is a character index or file location which will be used to augment the log with pos, loc (a standard { file, line, column } object) and frame (a snippet of code showing the location).

If the logLevel option is set to "silent", this method will do nothing.

[vercel]

The latest updates on your projects. Learn more about Vercel for Git ↗︎

Name	Status	Preview	Comments	Updated (UTC)
rollup	✅ Ready (Inspect)	Visit Preview	💬 Add feedback	Jun 10, 2023 4:49am

[github-actions]

Thank you for your contribution! ❤️

You can try out this pull request locally by installing Rollup via

npm install rollup/rollup#logging

or load it into the REPL:
https://rollup-1n5tpkx5v-rollup-js.vercel.app/repl/?pr=5026

[codecov]

Codecov Report

Merging #5026 (edfd187) into master (de2d6ff) will increase coverage by 0.01%.
The diff coverage is 99.61%.

@@            Coverage Diff             @@
##           master    #5026      +/-   ##
==========================================
+ Coverage   98.96%   98.97%   +0.01%     
==========================================
  Files         222      225       +3     
  Lines        8210     8295      +85     
  Branches     2258     2277      +19     
==========================================
+ Hits         8125     8210      +85     
  Misses         30       30              
  Partials       55       55              

Impacted Files	Coverage Δ
src/ast/nodes/Identifier.ts	100.00% <ø> (ø)
src/finalisers/index.ts	100.00% <ø> (ø)
src/utils/chunkAssignment.ts	100.00% <ø> (ø)
src/utils/hashPlaceholders.ts	100.00% <ø> (ø)
src/utils/renderNamePattern.ts	100.00% <ø> (ø)
src/utils/collapseSourcemaps.ts	90.42% <66.66%> (ø)
cli/run/batchWarnings.ts	100.00% <100.00%> (+0.82%)	⬆️
cli/run/build.ts	87.50% <100.00%> (-3.13%)	⬇️
cli/run/getConfigPath.ts	88.88% <100.00%> (ø)
cli/run/index.ts	100.00% <100.00%> (ø)
... and 37 more

[dominikg]

This is great ❤️

Ideas:

once wrapper

I think patak already mentioned it, but a once api would be a great convenience feature. In vite-plugin-svelte we use a custom logger that patches the log.<level> functions with a once wrapper, so you can do this.warn('foo') and it logs always, but this.warn.once('foo') would only do it once.
Very helpful to avoid spam.

enabled flag

Another helper we use is enabled as boolean, so this.debug.enabled && this.debug(expensiveCompute()) can be used to avoid extra work for disabled loggers.

inject plugin name,timestamp into log

If you have many plugins and some might log similar things, it can get hard to tell logs apart. formatting the logs to include plugin name and timestamp always would be nice.

debug scopes

Last but not least, the npm package debug offers scope support that can be configured via DEBUG=some-scope

If you scope this.debug calls to plugin-name:some-scope people can easily debug only one plugin or even parts of a plugin. Not sure if the scope could/should also include the called hook name, eg plugin-name:scope:hook This would allow much more fine grained output / limit the verbosity of debug logs.

[lukastaegert]

@dominikg Thanks for the feedback!

once wrapper

That is something we could add later, though I am still not convinced how necessary this feature is. It may be nice for debugging a plugin, but for logs that permanently stay in the plugin it should not be difficult to deduplicate within the plugin with a flag. On Rollup side, it would add some complexity that I would like to avoid.

And if we implement it with this chaining style, it would also create runtime overhead as the handler functions need to be recreated for some of the hooks for each invocation and plugin, which also means we need to always add the once handler. The effort might be lessened if I ever find the time to switch the context to a Proxy based approach, but I will not pursue this now.

enabled flag

I see the utility, but again runtime overhead is something I would like to reduce. I would have a different suggestion to address the same issue: Allow the log functions to receive a function creating the string/object instead of the log itself. Then your example would just become

this.debug(() => expensiveCompute())
// or this.debug(expensiveCompute)

and this would just incur a minimal overhead when actually logging instead of needing to create those "enabled" properties every time a transform hook runs.

debug scopes

I am not sure I would want to reuse the DEBUG environment variable from the debug package, but in general, log properties would be the equivalent of scopes.

This is the one idea I really want to push, but maybe I should make this even clearer in the docs: Rollup logs are objects, and you should give logs a code, pluginCode or other properties to add meta information so that it is easy to identify types of logs.

While you cannot do it from the command line, at the moment you can easily use the onLog option to filter for exactly the logs you want to see:

export default {
  //...
  onLog(level, log, handler) {
    if (log.plugin === 'node-resolve' && log.meta.scope === 'my-scope') {
      handler(level, log);
    }
  }
}

The log.meta.scope is just an example. In the TypeScript type of RollupLog, I added a meta attribute for adding custom information. The above would only display logs from node-resolve with this attribute.

Maybe I should add such an example to the docs.

One could consider turning this filtering into a CLI option, e.g. --filterLogs "plugin:node-resolve,meta.scope:my-scope". Then this could filter for any kind of logs, not only plugin ones, based on their attributes, e.g. --filterLogs code:MISSING_EXPORT,binding:foo. What do you think?

[lukastaegert]

I have added the ability to use functions as logs and updated the documentation.

[lukastaegert]

From my side, everything is finalized now. If there are no further comments, I would like to release it tomorrow.

[dominikg]

I like the ability to do it with env vars as you can do that even if rollup is called in a way where you can't pass args to it or would have to edit a config file.

The more generic way to filter logs by prop is nice!

[lukastaegert]

I like the ability to do it with env vars as you can do that even if rollup is called in a way where you can't pass args to it or would have to edit a config file.

Makes sense. I would add this as an additional improvement to not block the initial PR.

[lukastaegert]

@gajus This will make side effect logs filterable as they have a code of FIRST_SIDE_EFFECT and an id property corresponding to the current module.

[sapphi-red]

this.debug(() => expensiveCompute())

How about making this.debug/this.info/this.warn nullable?
Then, the caller can write this.debug?.(heavycomputation()).
heavycomputation won't be called; you can check it by:

let f = undefined
f?.(console.log('foo'))

I don't know which is better in terms of overhead.

[rollup-bot]

This PR has been released as part of rollup@3.25.0. You can test it via npm install rollup.

[sapphi-red]

That would be a breaking change if we do it with this.warn. Of course with the function approach, it is not that easy to polyfill this.debug.enabled, but you can still get the log level via the options in the buildStart hook.

Ah, that makes sense 👍

[lukastaegert]

@dominikg For filtering, see my proposal #5035