Repository: twisted/twisted

Issue:
twisted.logger doesn't execute methods despite documentation
|<img alt="ElementalAlchemist's avatar" src="https://avatars.githubusercontent.com/u/0?s=50" width="50" height="50">| 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).

<details><summary>Searchable metadata</summary>

```
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

```
</details>


Discussion:

Patch:
diff --git a/src/twisted/logger/_format.py b/src/twisted/logger/_format.py
index 4bc06ec40c..959f4867ad 100644
--- a/src/twisted/logger/_format.py
+++ b/src/twisted/logger/_format.py
@@ -6,6 +6,8 @@
 Tools for formatting logging events.
 """
 
+from __future__ import annotations
+
 from datetime import datetime as DateTime
 from typing import Any, Callable, Iterator, Mapping, Optional, Union, cast
 
@@ -164,6 +166,51 @@ def formatEventAsClassicLogText(
     return eventText + "\n"
 
 
+def keycall(key: str, getter: Callable[[str], Any]) -> PotentialCallWrapper:
+    """
+    Check to see if C{key} ends with parentheses ("C{()}"); if not, wrap up the
+    result of C{get} in a L{PotentialCallWrapper}.  Otherwise, call the result
+    of C{get} first, before wrapping it up.
+
+    @param key: The last dotted segment of a formatting key, as parsed by
+        L{Formatter.vformat}, which may end in C{()}.
+
+    @param getter: A function which takes a string and returns some other
+        object, to be formatted and stringified for a log.
+
+    @return: A L{PotentialCallWrapper} that will wrap up the result to allow
+        for subsequent usages of parens to defer execution to log-format time.
+    """
+    callit = key.endswith("()")
+    realKey = key[:-2] if callit else key
+    value = getter(realKey)
+    if callit:
+        value = value()
+    return PotentialCallWrapper(value)
+
+
+class PotentialCallWrapper(object):
+    """
+    Object wrapper that wraps C{getattr()} so as to process call-parentheses
+    C{"()"} after a dotted attribute access.
+    """
+
+    def __init__(self, wrapped: object) -> None:
+        self._wrapped = wrapped
+
+    def __getattr__(self, name: str) -> object:
+        return keycall(name, self._wrapped.__getattribute__)
+
+    def __format__(self, format_spec: str) -> str:
+        return self._wrapped.__format__(format_spec)
+
+    def __repr__(self) -> str:
+        return self._wrapped.__repr__()
+
+    def __str__(self) -> str:
+        return self._wrapped.__str__()
+
+
 class CallMapping(Mapping[str, Any]):
     """
     Read-only mapping that turns a C{()}-suffix in key names into an invocation
@@ -190,12 +237,7 @@ class CallMapping(Mapping[str, Any]):
         Look up an item in the submapping for this L{CallMapping}, calling it
         if C{key} ends with C{"()"}.
         """
-        callit = key.endswith("()")
-        realKey = key[:-2] if callit else key
-        value = self._submapping[realKey]
-        if callit:
-            value = value()
-        return value
+        return keycall(key, self._submapping.__getitem__)
 
 
 def formatWithCall(formatString: str, mapping: Mapping[str, Any]) -> str:
diff --git a/src/twisted/newsfragments/9347.bugfix b/src/twisted/newsfragments/9347.bugfix
new file mode 100644
index 0000000000..2dbfc1676b
--- /dev/null
+++ b/src/twisted/newsfragments/9347.bugfix
@@ -0,0 +1,4 @@
+twisted.logger.formatEvent now honors dotted method names, not just flat
+function names, in format strings, as it has long been explicitly documented to
+do.  So, you will now get the expected result from `formatEvent("here's the
+result of calling a method at log-format time: {obj.method()}", obj=...)`


Test patch:
diff --git a/src/twisted/logger/test/test_format.py b/src/twisted/logger/test/test_format.py
index 67dbf0ce78..6c830ca9f2 100644
--- a/src/twisted/logger/test/test_format.py
+++ b/src/twisted/logger/test/test_format.py
@@ -36,6 +36,17 @@ class FormattingTests(unittest.TestCase):
     Tests for basic event formatting functions.
     """
 
+    def format(self, logFormat: AnyStr, **event: object) -> str:
+        """
+        Create a Twisted log event dictionary from C{event} with the given
+        C{logFormat} format string, format it with L{formatEvent}, ensure that
+        its type is L{str}, and return its result.
+        """
+        event["log_format"] = logFormat
+        result = formatEvent(event)
+        self.assertIs(type(result), str)
+        return result
+
     def test_formatEvent(self) -> None:
         """
         L{formatEvent} will format an event according to several rules:
@@ -53,27 +64,36 @@ class FormattingTests(unittest.TestCase):
         L{formatEvent} will always return L{str}, and if given bytes, will
         always treat its format string as UTF-8 encoded.
         """
-
-        def format(logFormat: AnyStr, **event: object) -> str:
-            event["log_format"] = logFormat
-            result = formatEvent(event)
-            self.assertIs(type(result), str)
-            return result
-
-        self.assertEqual("", format(b""))
-        self.assertEqual("", format(""))
-        self.assertEqual("abc", format("{x}", x="abc"))
+        self.assertEqual("", self.format(b""))
+        self.assertEqual("", self.format(""))
+        self.assertEqual("abc", self.format("{x}", x="abc"))
         self.assertEqual(
             "no, yes.",
-            format("{not_called}, {called()}.", not_called="no", called=lambda: "yes"),
+            self.format(
+                "{not_called}, {called()}.", not_called="no", called=lambda: "yes"
+            ),
         )
-        self.assertEqual("S\xe1nchez", format(b"S\xc3\xa1nchez"))
-        self.assertIn("Unable to format event", format(b"S\xe1nchez"))
-        maybeResult = format(b"S{a!s}nchez", a=b"\xe1")
+        self.assertEqual("S\xe1nchez", self.format(b"S\xc3\xa1nchez"))
+        self.assertIn("Unable to format event", self.format(b"S\xe1nchez"))
+        maybeResult = self.format(b"S{a!s}nchez", a=b"\xe1")
         self.assertIn("Sb'\\xe1'nchez", maybeResult)
 
         xe1 = str(repr(b"\xe1"))
-        self.assertIn("S" + xe1 + "nchez", format(b"S{a!r}nchez", a=b"\xe1"))
+        self.assertIn("S" + xe1 + "nchez", self.format(b"S{a!r}nchez", a=b"\xe1"))
+
+    def test_formatMethod(self) -> None:
+        """
+        L{formatEvent} will format PEP 3101 keys containing C{.}s ending with
+        C{()} as methods.
+        """
+
+        class World:
+            def where(self) -> str:
+                return "world"
+
+        self.assertEqual(
+            "hello world", self.format("hello {what.where()}", what=World())
+        )
 
     def test_formatEventNoFormat(self) -> None:
         """