Merge pull request #2071 from valory-xyz/fix/log-parser

Fix multiline log parsing

autonomy/analyse/logs/base.py

@@ -29,7 +29,7 @@
 TIME_FORMAT = "%Y-%m-%d %H:%M:%S,%f"
 TIMESTAMP_REGEX = re.compile(r"^(\[(\d+-\d+-\d+ \d+:\d+:\d+,\d+)\])")
 LOG_ROW_REGEX = re.compile(
-    r"\[(\d+-\d+-\d+ \d+:\d+:\d+,\d+)\] \[([A-Z]+)\]( \[agent\])? (.*)"
+    r"\[(\d+-\d+-\d+ \d+:\d+:\d+,\d+)\] \[([A-Z]+)\]( \[agent\])? ((.|\n)*)"
 )
 ENTER_BEHAVIOUR_REGEX = re.compile(r"Entered in the \'([a-z_]+)\' behaviour")
 ENTER_ROUND_REGEX = re.compile(r"Entered in the \'([a-z_]+)\' round for period (\d+)")

autonomy/analyse/logs/collection.py

@@ -61,18 +61,21 @@ def create_agent_db(
 
     @staticmethod
     def get_next_log_block(
-        fp: TextIO, prev_line: str
+        fp: TextIO,
+        prev_line: Optional[str],
     ) -> Tuple[Optional[str], Optional[str]]:
         """Get next log block."""
+        if prev_line is None:
+            return None, None
 
         line = prev_line
         while True:
             _line = fp.readline()
             if _line == "":
-                return None, None
+                return prev_line, None
             if TIMESTAMP_REGEX.match(_line) is not None:
                 return line, _line
-            line += line
+            line += _line
 
     @classmethod
     def parse(cls, file: Path) -> Generator[LogRow, None, None]:
@@ -83,16 +86,13 @@ def parse(cls, file: Path) -> Generator[LogRow, None, None]:
             current_round = "agent_startup"
             current_behaviour = "agent_startup"
             while True:
-                line, prev_line = cls.get_next_log_block(
-                    fp=fp, prev_line=cast(str, prev_line)
-                )
+                line, prev_line = cls.get_next_log_block(fp=fp, prev_line=prev_line)
                 if line is None and prev_line is None:
                     break
 
                 match = LOG_ROW_REGEX.match(string=cast(str, line))
-                _timestamp, log_level, _, log_block = cast(re.Match, match).groups()
+                _timestamp, log_level, _, log_block, _ = cast(re.Match, match).groups()
                 timestamp = datetime.strptime(_timestamp, TIME_FORMAT)
-
                 match = ENTER_BEHAVIOUR_REGEX.match(string=log_block)
                 if match is not None:
                     (current_behaviour,) = match.groups()

docs/api/analyse/logs/collection.md

@@ -54,8 +54,9 @@ Create logs database.
 
 ```python
 @staticmethod
-def get_next_log_block(fp: TextIO,
-                       prev_line: str) -> Tuple[Optional[str], Optional[str]]
+def get_next_log_block(
+        fp: TextIO,
+        prev_line: Optional[str]) -> Tuple[Optional[str], Optional[str]]
 ```
 
 Get next log block.

tests/test_autonomy/test_analyse/test_logs.py

@@ -0,0 +1,72 @@
+# -*- coding: utf-8 -*-
+# ------------------------------------------------------------------------------
+#
+#   Copyright 2023 Valory AG
+#
+#   Licensed under the Apache License, Version 2.0 (the "License");
+#   you may not use this file except in compliance with the License.
+#   You may obtain a copy of the License at
+#
+#       http://www.apache.org/licenses/LICENSE-2.0
+#
+#   Unless required by applicable law or agreed to in writing, software
+#   distributed under the License is distributed on an "AS IS" BASIS,
+#   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+#   See the License for the specific language governing permissions and
+#   limitations under the License.
+#
+# ------------------------------------------------------------------------------
+
+"""Test log parser."""
+
+import tempfile
+from pathlib import Path
+
+from autonomy.analyse.logs.collection import LogCollection
+
+
+LOGS = """[2023-09-26 06:27:56,015] [INFO] [agent] Entered in the 'check_transaction_history_behaviour' behaviour
+[2023-09-26 06:27:56,078] [ERROR] [agent] get_safe_nonce unsuccessful! Received: Message(sender=valory/ledger:0.19.0,to=valory/trader_abci:0.1.0,code=500,data=b'',dialogue_reference=('974278ff7b4e00019f7542a193987a8359b1c785d11a98a84bfaff2ea77b1e8f', '6b8e33fe183de2ac45e8d8f9625db5562b6230677fdc6995efc4ce05c798f83a'),message=Traceback (most recent call last):
+
+  File "/usr/lib/python3.10/http/client.py", line 287, in _read_status
+    raise RemoteDisconnected("Remote end closed connection without"
+
+http.client.RemoteDisconnected: Remote end closed connection without response
+
+
+During handling of the above exception, another exception occurred:
+
+
+Traceback (most recent call last):
+
+  File "/usr/lib/python3.10/http/client.py", line 287, in _read_status
+    raise RemoteDisconnected("Remote end closed connection without"
+
+urllib3.exceptions.ProtocolError: ('Connection aborted.', RemoteDisconnected('Remote end closed co,message_id=-1,performative=error,target=1)
+[2023-09-26 06:27:56,103] [INFO] [agent] arrived block with timestamp: 2023-09-26 06:27:55.040545
+"""
+
+LOGS_CLEAN = """Entered in the 'check_transaction_history_behaviour' behaviour
+get_safe_nonce unsuccessful! Received: Message(sender=valory/ledger:0.19.0,to=valory/trader_abci:0.1.0,code=500,data=b'',dialogue_reference=('974278ff7b4e00019f7542a193987a8359b1c785d11a98a84bfaff2ea77b1e8f', '6b8e33fe183de2ac45e8d8f9625db5562b6230677fdc6995efc4ce05c798f83a'),message=Traceback (most recent call last):
+File "/usr/lib/python3.10/http/client.py", line 287, in _read_status
+raise RemoteDisconnected("Remote end closed connection without"
+http.client.RemoteDisconnected: Remote end closed connection without response
+During handling of the above exception, another exception occurred:
+Traceback (most recent call last):
+File "/usr/lib/python3.10/http/client.py", line 287, in _read_status
+raise RemoteDisconnected("Remote end closed connection without"
+urllib3.exceptions.ProtocolError: ('Connection aborted.', RemoteDisconnected('Remote end closed co,message_id=-1,performative=error,target=1)
+arrived block with timestamp: 2023-09-26 06:27:55.040545
+"""
+
+
+def test_multiline_parse() -> None:
+    """Test multiline logs parsing."""
+
+    with tempfile.TemporaryDirectory() as temp_dir:
+        file = Path(temp_dir, "log.txt")
+        file.write_text(LOGS)
+        parsed = "\n".join(list(map(lambda x: x[2], LogCollection.parse(file=file))))
+
+        for line in LOGS_CLEAN.split("\n"):
+            assert line in parsed