Repository: XKNX/xknx
Pull request #1107 (2022-12-18 10:22:08)

Add `xknx.cemi` logger
<!--
  You are awesome! Thanks for contributing to our project!
  Please, DO NOT DELETE ANY TEXT from this template!.
-->
## Description
<!--
Please include a summary of the change and which issue is fixed.
Please also include relevant motivation and context.
List any dependencies that are required for this change.
-->
- Add new logger `xknx.cemi` for incoming and outgoing CEMIFrames.
- Remove timestamp and line break in knx and raw logger. HA logging now has millisecond precision so I guess we don't need the additional timestamp anymore.

The logging game in HA now looks like this:
```log
2022-12-18 11:50:28.774 DEBUG (KNX Interface) [xknx.raw_socket] Received via tcp: 061004200015040255002900bce0101f0831010080
2022-12-18 11:50:28.774 DEBUG (KNX Interface) [xknx.knx] Received from 10.1.0.41:3671/tcp: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="TUNNELLING_REQUEST" Reserve="0" TotalLength="21" /> body="<TunnellingRequest communication_channel_id="2" sequence_counter="85" cemi="2900bce0101f0831010080" />" />
2022-12-18 11:50:28.774 DEBUG (KNX Interface) [xknx.cemi] Incoming CEMI: <CEMIFrame code="L_DATA_IND" src_addr="IndividualAddress("1.0.31")" dst_addr="GroupAddress("1/0/49")" flags="1011110011100000" tpci="TDataGroup()" payload="<GroupValueWrite value="<DPTBinary value="0" />" />" />
2022-12-18 11:50:28.777 DEBUG (MainThread) [xknx.telegram] <Telegram direction="Incoming" source_address="1.0.31" destination_address="1/0/49" payload="<GroupValueWrite value="<DPTBinary value="0" />" />" />
```

Fixes # (issue)

## Type of change
<!--
Please tick the applicable options.
NOTE: Ticking multiple options most likely indicates
that your change is to big and it is suggested to split it into several smaller PRs.
-->

- [ ] Bug fix (non-breaking change which fixes an issue)
- [ ] New feature (non-breaking change which adds functionality)
- [ ] Breaking change (fix or feature that would cause existing functionality to not work as expected)
- [ ] This change requires a documentation update

## Checklist:

- [ ] The documentation has been adjusted accordingly
- [ ] Tests have been added that prove the fix is effective or that the feature works
- [x] The changes are documented in the changelog (docs/changelog.md)

codecov[bot]: # [Codecov](https://codecov.io/gh/XKNX/xknx/pull/1107?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX) Report
> Merging [#1107](https://codecov.io/gh/XKNX/xknx/pull/1107?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX) (09b4e16) into [main](https://codecov.io/gh/XKNX/xknx/commit/1319934147089dae0bff38bc3590ccb3f8534769?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX) (1319934) will **not change** coverage.
> The diff coverage is `100.00%`.

> :exclamation: Current head 09b4e16 differs from pull request most recent head ced4bc6. Consider uploading reports for the commit ced4bc6 to get more accurate results

[![Impacted file tree graph](https://codecov.io/gh/XKNX/xknx/pull/1107/graphs/tree.svg?width=650&height=150&src=pr&token=irWbIygS84&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX)](https://codecov.io/gh/XKNX/xknx/pull/1107?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX)

```diff
@@           Coverage Diff           @@
##             main    #1107   +/-   ##
=======================================
  Coverage   96.34%   96.34%           
=======================================
  Files         138      138           
  Lines        8643     8643           
=======================================
  Hits         8327     8327           
  Misses        316      316           
```


| [Impacted Files](https://codecov.io/gh/XKNX/xknx/pull/1107?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX) | Coverage Δ | |
|---|---|---|
| [xknx/io/transport/tcp\_transport.py](https://codecov.io/gh/XKNX/xknx/pull/1107/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX#diff-eGtueC9pby90cmFuc3BvcnQvdGNwX3RyYW5zcG9ydC5weQ==) | `46.55% <ø> (-0.91%)` | :arrow_down: |
| [xknx/io/transport/udp\_transport.py](https://codecov.io/gh/XKNX/xknx/pull/1107/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX#diff-eGtueC9pby90cmFuc3BvcnQvdWRwX3RyYW5zcG9ydC5weQ==) | `50.00% <ø> (-0.69%)` | :arrow_down: |
| [xknx/knxip/knxip.py](https://codecov.io/gh/XKNX/xknx/pull/1107/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX#diff-eGtueC9rbnhpcC9rbnhpcC5weQ==) | `100.00% <ø> (ø)` | |
| [xknx/io/routing.py](https://codecov.io/gh/XKNX/xknx/pull/1107/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX#diff-eGtueC9pby9yb3V0aW5nLnB5) | `91.91% <100.00%> (+0.05%)` | :arrow_up: |
| [xknx/io/tunnel.py](https://codecov.io/gh/XKNX/xknx/pull/1107/diff?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=XKNX#diff-eGtueC9pby90dW5uZWwucHk=) | `88.33% <100.00%> (+0.04%)` | :arrow_up: |


Patch:
diff --git a/docs/changelog.md b/docs/changelog.md
index 9f127541..2cc605ca 100644
--- a/docs/changelog.md
+++ b/docs/changelog.md
@@ -17,6 +17,8 @@ nav_order: 2
 - Add `task.done()` to TaskRegistry tasks.
 - Decouple KNXIPFrame parsing from CEMIFrame parsing. TunnellingRequest and RoutingIndication now carry the raw cemi frame payload as bytes. This allows decoupled CEMIFrame parsing at a later time (in Interface class rather than in KNXIPTransport class) for better error handling and upcoming features.
 - Make KNXIPFrame body non-optional. Return KNXIPFrame object and remaining bytes from `KNXIPFrame.from_knx()` staticmethod.
+- Add new logger `xknx.cemi` for incoming and outgoing CEMIFrames.
+- Remove timestamp and line break in knx and raw logger.
 
 # 2.1.0 Enhance notification device
 
diff --git a/xknx/io/routing.py b/xknx/io/routing.py
index aa41c43a..936e9c47 100644
--- a/xknx/io/routing.py
+++ b/xknx/io/routing.py
@@ -35,6 +35,7 @@ if TYPE_CHECKING:
     from xknx.xknx import XKNX
 
 logger = logging.getLogger("xknx.log")
+cemi_logger = logging.getLogger("xknx.cemi")
 
 BUSY_DECREMENT_TIME: Final = 0.005  # 5 ms
 BUSY_INCREMENT_COOLDOWN: Final = 0.01  # 10 ms
@@ -223,6 +224,7 @@ class Routing(Interface):
             code=CEMIMessageCode.L_DATA_IND,
             src_addr=self.individual_address,
         )
+        cemi_logger.debug("Outgoing CEMI: %s", cemi)
         routing_indication = RoutingIndication(raw_cemi=cemi.to_knx())
 
         async with self._flow_control.throttle():
@@ -260,6 +262,7 @@ class Routing(Interface):
         cemi = CEMIFrame()
         try:
             cemi.from_knx(routing_indication.raw_cemi)
+            cemi_logger.debug("Incoming CEMI: %s", cemi)
         except UnsupportedCEMIMessage as unsupported_cemi_err:
             logger.warning("CEMI not supported: %s", unsupported_cemi_err)
             return
diff --git a/xknx/io/transport/tcp_transport.py b/xknx/io/transport/tcp_transport.py
index 80eb04d4..259d63f3 100644
--- a/xknx/io/transport/tcp_transport.py
+++ b/xknx/io/transport/tcp_transport.py
@@ -7,7 +7,6 @@ from __future__ import annotations
 
 import asyncio
 import logging
-import time
 from typing import Callable, cast
 
 from xknx.exceptions import CommunicationError, CouldNotParseKNXIP, IncompleteKNXIPFrame
@@ -81,17 +80,15 @@ class TCPTransport(KNXIPTransport):
             return
         except CouldNotParseKNXIP as couldnotparseknxip:
             knx_logger.debug(
-                "Unsupported KNXIPFrame from %s at %s: %s in %s",
+                "Unsupported KNXIPFrame from %s: %s in %s",
                 self.remote_hpai,
-                time.time(),
                 couldnotparseknxip.description,
                 raw.hex(),
             )
         else:
             knx_logger.debug(
-                "Received from %s at %s:\n%s",
+                "Received from %s: %s",
                 self.remote_hpai,
-                time.time(),
                 knxipframe,
             )
             self.handle_knxipframe(knxipframe, self.remote_hpai)
@@ -125,9 +122,8 @@ class TCPTransport(KNXIPTransport):
     def send(self, knxipframe: KNXIPFrame, addr: tuple[str, int] | None = None) -> None:
         """Send KNXIPFrame to socket. `addr` is ignored on TCP."""
         knx_logger.debug(
-            "Sending to %s at %s:\n%s",
+            "Sending to %s: %s",
             self.remote_hpai,
-            time.time(),
             knxipframe,
         )
         if self.transport is None:
diff --git a/xknx/io/transport/udp_transport.py b/xknx/io/transport/udp_transport.py
index 1c601d3d..4d6cbd77 100644
--- a/xknx/io/transport/udp_transport.py
+++ b/xknx/io/transport/udp_transport.py
@@ -10,7 +10,6 @@ import asyncio
 import logging
 import socket
 from sys import platform
-import time
 from typing import Callable, cast
 
 from xknx.exceptions import CommunicationError, CouldNotParseKNXIP
@@ -81,19 +80,17 @@ class UDPTransport(KNXIPTransport):
                 knxipframe, _ = KNXIPFrame.from_knx(raw)
             except CouldNotParseKNXIP as couldnotparseknxip:
                 knx_logger.debug(
-                    "Unsupported KNXIPFrame from %s:%s at %s: %s in %s",
+                    "Unsupported KNXIPFrame from %s:%s: %s in %s",
                     source[0],
                     source[1],
-                    time.time(),
                     couldnotparseknxip.description,
                     raw.hex(),
                 )
             else:
                 knx_logger.debug(
-                    "Received from %s:%s at %s:\n %s",
+                    "Received from %s:%s: %s",
                     source[0],
                     source[1],
-                    time.time(),
                     knxipframe,
                 )
                 self.handle_knxipframe(knxipframe, HPAI(*source))
@@ -159,9 +156,7 @@ class UDPTransport(KNXIPTransport):
     def send(self, knxipframe: KNXIPFrame, addr: tuple[str, int] | None = None) -> None:
         """Send KNXIPFrame to socket."""
         _addr = addr or self.remote_addr
-        knx_logger.debug(
-            "Sending to %s:%s at %s:\n %s", _addr[0], _addr[1], time.time(), knxipframe
-        )
+        knx_logger.debug("Sending to %s:%s: %s", _addr[0], _addr[1], knxipframe)
         if self.transport is None:
             raise CommunicationError("Transport not connected")
 
diff --git a/xknx/io/tunnel.py b/xknx/io/tunnel.py
index 95cc4cf8..20833f81 100644
--- a/xknx/io/tunnel.py
+++ b/xknx/io/tunnel.py
@@ -45,6 +45,7 @@ if TYPE_CHECKING:
     from xknx.xknx import XKNX
 
 logger = logging.getLogger("xknx.log")
+cemi_logger = logging.getLogger("xknx.cemi")
 
 # See 3/6/3 EMI_IMI §4.1.5 Data Link Layer messages
 REQUEST_TO_CONFIRMATION_TIMEOUT = 3
@@ -274,6 +275,7 @@ class _Tunnel(Interface):
         A transport layer confirmation shall be awaited before sending the next telegram.
         """
         async with self._send_telegram_lock:
+            cemi_logger.debug("Outgoing CEMI: %s", cemi)
             skip_increase_sequence_number = False
             try:
                 await self._tunnelling_request(cemi)
@@ -354,6 +356,7 @@ class _Tunnel(Interface):
         cemi = CEMIFrame()
         try:
             cemi.from_knx(tunneling_request.raw_cemi)
+            cemi_logger.debug("Incoming CEMI: %s", cemi)
         except UnsupportedCEMIMessage as unsupported_cemi_err:
             logger.warning("CEMI not supported: %s", unsupported_cemi_err)
             return
@@ -519,6 +522,7 @@ class UDPTunnel(_Tunnel):
         control endpoint.
         """
         async with self._send_telegram_lock:
+            cemi_logger.debug("Outgoing CEMI: %s", cemi)
             try:
                 try:
                     await self._tunnelling_request(cemi)
diff --git a/xknx/knxip/knxip.py b/xknx/knxip/knxip.py
index 4155d54f..dd10b1b1 100644
--- a/xknx/knxip/knxip.py
+++ b/xknx/knxip/knxip.py
@@ -133,7 +133,7 @@ class KNXIPFrame:
 
     def __repr__(self) -> str:
         """Return object as readable string."""
-        return f'<KNXIPFrame {self.header}\n body="{self.body}" />'
+        return f'<KNXIPFrame {self.header} body="{self.body}" />'
 
     def __eq__(self, other: object) -> bool:
         """Equal operator."""
diff --git a/xknx/xknx.py b/xknx/xknx.py
index 59388b72..cb675f44 100644
--- a/xknx/xknx.py
+++ b/xknx/xknx.py
@@ -176,6 +176,7 @@ class XKNX:
         _handler.setLevel(logging.DEBUG)
 
         for log_namespace in [
+            "xknx.cemi",
             "xknx.log",
             "xknx.knx",
             "xknx.raw_socket",


Test patch:
diff --git a/test/str_test.py b/test/str_test.py
index 0cfd21c5..19b1c1d4 100644
--- a/test/str_test.py
+++ b/test/str_test.py
@@ -660,8 +660,7 @@ class TestStringRepresentations:
         assert (
             str(knxipframe)
             == '<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="SEARCH_REQUEST" '
-            'Reserve="0" TotalLength="14" />\n'
-            ' body="<SearchRequest discovery_endpoint="0.0.0.0:0/udp" />" />'
+            'Reserve="0" TotalLength="14" /> body="<SearchRequest discovery_endpoint="0.0.0.0:0/udp" />" />'
         )
 
     #