ashb commented on code in PR #54433:
URL: https://github.com/apache/airflow/pull/54433#discussion_r2276246901


##########
task-sdk/src/airflow/sdk/log.py:
##########
@@ -243,6 +276,14 @@ def json_processor(logger: Any, method_name: Any, 
event_dict: EventDict) -> str:
         (
             dict_tracebacks,
             structlog.processors.UnicodeDecoder(),
+            structlog.processors.CallsiteParameterAdder(
+                {
+                    structlog.processors.CallsiteParameter.FUNC_NAME,
+                    structlog.processors.CallsiteParameter.LINENO,
+                    structlog.processors.CallsiteParameter.PATHNAME,
+                }
+            ),
+            custom_format,

Review Comment:
   Sorry no - this is flat out not acceptable. We use structlog to a) get 
structured log fields, and b) to be more performant. Sending every single log 
message through a stdlib log formatter is not acceptable. 



##########
task-sdk/src/airflow/sdk/execution_time/supervisor.py:
##########
@@ -1610,6 +1610,7 @@ def process_log_messages_from_subprocess(
 
         level = NAME_TO_LEVEL[event.pop("level")]
         msg = event.pop("event", None)
+        event["chan"] = "logs"

Review Comment:
   This adds noise to every single log line -- why do we need it?



##########
providers/amazon/tests/unit/amazon/aws/log/test_cloudwatch_task_handler.py:
##########
@@ -47,6 +48,8 @@
 from tests_common.test_utils.config import conf_vars
 from tests_common.test_utils.version_compat import AIRFLOW_V_3_0_PLUS
 
+settings.LOG_FORMAT = "%(message)s"

Review Comment:
   This is going to leak state to other tests so isn't right.
   
   Additionally why is this needed? What does it do?



##########
task-sdk/src/airflow/sdk/log.py:
##########
@@ -116,6 +118,37 @@ def drop_positional_args(logger: Any, method_name: Any, 
event_dict: EventDict) -
     return event_dict
 
 
+def custom_format(logger: Any, method_name: Any, event_dict: EventDict) -> 
EventDict:
+    record = event_dict.get("_record", None)
+    func_name = event_dict.pop("func_name", "")
+    warning_lineno = event_dict.pop("warning_lineno", "")
+    lineno = event_dict.pop("lineno", 0)
+    lineno = warning_lineno or lineno
+    warning_pathname = event_dict.pop("warning_pathname", "")
+    pathname = event_dict.pop("pathname", "")
+    pathname = warning_pathname or pathname
+    # Ignore the logs forwarded from subprocess, otherwise we got wrong 
callsite
+    if (chan := event_dict.get("chan", None)) and chan == "logs":
+        event_dict.pop("chan")
+        return event_dict
+    if not record:
+        # Build LogRecord to format log for stderr, stdout and warnings
+        record = logging.LogRecord(
+            name=event_dict.get("logger", ""),
+            level=structlog.stdlib.NAME_TO_LEVEL[event_dict.get("level", "")],
+            pathname=pathname,
+            lineno=lineno,
+            msg=event_dict.get("event", ""),
+            args=event_dict.pop("positional_args", ()),
+            exc_info=event_dict.pop("exc_info", None),
+            func=func_name,
+        )
+    record.msg = event_dict.pop("event", "")
+    formatter = logging.Formatter(settings.LOG_FORMAT)

Review Comment:
   A number of things need changing here:
   
   1. Creating a new formatter for every single stdlib log message received is 
going to massively hurt performance
   2. we want everything as structured JSON fields, not plain text. So we can't 
us stdlib formatters really.
   3. This entire function is complicated and hard to work out what it's 
actually doing?  I wrote all the rest of the logging code and _I_ can't work it 
out so we need to refactor this so the intent is clearer. What does this fn do?



##########
airflow-core/src/airflow/config_templates/config.yml:
##########
@@ -850,7 +850,7 @@ logging:
       version_added: 2.0.0
       type: string
       example: ~
-      default: "[%%(asctime)s] {{%%(filename)s:%%(lineno)d}} %%(levelname)s - 
%%(message)s"
+      default: "{{%%(filename)s:%%(lineno)d}} - %%(message)s"

Review Comment:
   Why did we change this? It doesn't have any effect does it?



##########
task-sdk/tests/task_sdk/execution_time/test_supervisor.py:
##########
@@ -266,37 +276,35 @@ def subprocess_main():
             [
                 {
                     "chan": "stdout",
-                    "event": "I'm a short message",
+                    "event": "supervisor.py: I'm a short message",

Review Comment:
   This defeats the purpose of structlog.
   ```suggestion
                       "event": "I'm a short message",
                       "filename": "supervisor.py"
   ```
   
   etc



-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: [email protected]

For queries about this service, please contact Infrastructure at:
[email protected]

Reply via email to