twisted.logger doesn't execute methods despite documentation

[twisted-trac]

	ElementalAlchemist reported
Trac ID	trac#9347
Type	defect
Created	2017-12-06 02:56:36Z

It may come up that people want to log things based on data gotten from object methods, e.g.

self.ircd.log.debug("Disconnecting user {user.uuid} ({user.hostmask()}): {reason}", user=self, reason=reason)

where user.hostmask() is some sort of useful data.

According to the documentation (https://twistedmatrix.com/documents/16.1.1/core/howto/logger.html#format-strings), not only is this allowed, but there is an example showing that this is explicitly allowed.

However, attempting to log the above message results in Twisted logging something like this:

2017-12-05 20:52:26-0600 [-] Unable to format event {'log_namespace': 'txircd', 'log_level': <LogLevel=debug>, 'format': '%(log_legacy)s', 'log_logger': <Logger 'txircd'>, 'log_source': None, 'system': '-', 'reason': 'Registration timeout', 'user': <txircd.user.IRCUser instance at 0x7f0c092e8050>, 'time': 1512528746.643236, 'log_format': 'Disconnecting user {user.uuid} ({user.hostmask()}): {reason}', 'message': (), 'log_time': 1512528746.643236}: IRCUser instance has no attribute 'hostmask()'

Instead, in order to get the desired logging, you need to modify it so that the functions aren't run on objects in the string:

self.ircd.log.debug("Disconnecting user {user.uuid} ({hostmask()}): {reason}", user=self, hostmask=self.hostmask, reason=reason)

This logs as expected, but the need to change to this doesn't match up with what the documentation says.

Either object methods need to be allowed, or the documentation needs to be changed to disallow it (including modifying the example where an object method is explicitly used in this way).

Searchable metadata

trac-id__9347 9347
type__defect defect
reporter__ElementalAlchemist ElementalAlchemist
priority__normal normal
milestone__None None
branch__ 
branch_author__ 
status__new new
resolution__None None
component__logger logger
keywords__None None
time__1512528996358368 1512528996358368
changetime__1513653408400714 1513653408400714
version__None None
owner__None None

[number492]

Still reproducible with 23.10.0.

[glyph]

@number492 Thanks for bumping this.

[glyph]

@number492 if you'd like to code-review the fix in #12040, and CI is happy, we can land it and get this addressed in the next release.

[number492]

@number492 if you'd like to code-review the fix in #12040, and CI is happy, we can land it and get this addressed in the next release.

Sure, I checked it out and it looks good. I'm not a contributor though, and I'm not familiar with the project's conventions.

[number492]

Thanks for the quick fix!

[glyph]

Thanks for the quick fix!

You're welcome. Thanks for the bug report!