Unexpected String Concatenation Issue in Airflow 2.7.2

[artemSSSS]

Apache Airflow version

Other Airflow 2 version (please specify below)

If "Other Airflow 2 version" selected, which one?

2.7.2

What happened?

I am encountering an unexpected issue with string concatenation in Airflow 2.7.2 using Python 3.11.5. The issue only occurs in Airflow, while the same string concatenation works correctly in local unit tests.

What you think should happen instead?

The concatenated string values_str_3 should be correctly formatted and match the output of values_str and values_str_2

How to reproduce

Use the following code snippet in an Airflow DAG or script:

values = ['1234', '5678', 'ABC_123', 'xyz-calc', '2024-01-01', 'NULL', '9876', 'NULL', 'example', 42, '2024-07-28T01:23:45.678', '2024-07-28T02:34:56.789', '2024-07-28T03:45:67.890', 'user_test', 'complete', '2024-07-28T04:56:78.901', '2024-07-28T05:67:89.012', 'NULL', 'spark-calc-1234-driver', 'NULL', 'NULL', 'XYZ']

values_str_list = []
for value in values:
    if isinstance(value, int):
        values_str_list.append(str(value))
    elif value == 'NULL':
        values_str_list.append('NULL')
    else:
        values_str_list.append(f"'{value}'")

values_str = ','.join(values_str_list)  # This concatenation works correctly
print("Concatenated string values_str:")
print(values_str)

values_str_2 = ', '.join(values_str_list)  # This concatenation works correctly
print("Concatenated string values_str_2:")
print(values_str_2)

values_str_3 = ',\n    '.join(values_str_list)  # This concatenation does NOT work correctly
print("Concatenated string values_str_3:")
print(values_str_3)
logging.info("Concatenated string values_str_3:")
logging.info(values_str_3)

The concatenated string values_str_3 is incorrectly formatted in Airflow logs.

Logs:

[2024-07-29, 22:12:39 UTC] {logging_mixin.py:151} INFO - Concatenated string values_str:
[2024-07-29, 22:12:39 UTC] {logging_mixin.py:151} INFO - 1234,5678,'ABC_123','xyz-calc','2024-01-01',NULL,'9876',NULL,'example',42,'2024-07-28T01:23:45.678','2024-07-28T02:34:56.789','2024-07-28T03:45:67.890','user_test','complete','2024-07-28T04:56:78.901','2024-07-28T05:67:89.012',NULL,'spark-calc-1234-driver',NULL,NULL,'XYZ'
[2024-07-29, 22:12:39 UTC] {logging_mixin.py:151} INFO - Concatenated string values_str_2:
[2024-07-29, 22:12:39 UTC] {logging_mixin.py:151} INFO - 1234, 5678, 'ABC_123', 'xyz-calc', '2024-01-01', NULL, '9876', NULL, 'example', 42, '2024-07-28T01:23:45.678', '2024-07-28T02:34:56.789', '2024-07-28T03:45:67.890', 'user_test', 'complete', '2024-07-28T04:56:78.901', '2024-07-28T05:67:89.012', NULL, 'spark-calc-1234-driver', NULL, NULL, 'XYZ'
[2024-07-29, 22:12:39 UTC] {logging_mixin.py:151} INFO - Concatenated string values_str_3:
[2024-07-29, 22:12:39 UTC] {logging_mixin.py:151} INFO - 1234,
    5678,
    'ABC_123',
    'xyz-calc',
    '2024-01-01',
    NULL,
    '9876',
    NULL,
    'example',
    42,
    '2024-07-28T01:23:45.678',
    '2024-07-28T02:34:56.789',
    '2024-07-28T03:45:67.890',
    'user_test',
    'complete',
    '2024-07-28T04:56:78.901',
    '2024-07-28T05:67:89.012',
    NULL,
    'spark-calc-1234-driver',
    NULL,
    'XYZ'
[2024-07-29, 22:12:39 UTC] INFO - Concatenated string values_str_3:
[2024-07-29, 22:12:39 UTC] INFO - 1234,
    5678,
    'ABC_123',
    'xyz-calc',
    '2024-01-01',
    NULL,
    '9876',
    NULL,
    'example',
    42,
    '2024-07-28T01:23:45.678',
    '2024-07-28T02:34:56.789',
    '2024-07-28T03:45:67.890',
    'user_test',
    'complete',
    '2024-07-28T04:56:78.901',
    '2024-07-28T05:67:89.012',
    NULL,
    'spark-calc-1234-driver',
    NULL,
    'XYZ'

Operating System

Linux

Versions of Apache Airflow Providers

No response

Deployment

Docker-Compose

Deployment details

No response

Anything else?

Interestingly, when the concatenated string is split, the result is correct:

print("Original string values_str:", values_str.split(','))
print("Original string values_str_2:", values_str_2.split(', '))
print("Original string values_str_3:", values_str_3.split(',\n    '))

Logs:

[2024-07-29, 22:12:39 UTC] {logging_mixin.py:151} INFO - Original string values_str: ['1234', '5678', "'ABC_123'", "'xyz-calc'", "'2024-01-01'", 'NULL', "'9876'", 'NULL', "'example'", '42', "'2024-07-28T01:23:45.678'", "'2024-07-28T02:34:56.789'", "'2024-07-28T03:45:67.890'", "'user_test'", "'complete'", "'2024-07-28T04:56:78.901'", "'2024-07-28T05:67:89.012'", 'NULL', "'spark-calc-1234-driver'", 'NULL', 'NULL', "'XYZ'"]
[2024-07-29, 22:12:39 UTC] {logging_mixin.py:151} INFO - Original string values_str_2: ['1234', '5678', "'ABC_123'", "'xyz-calc'", "'2024-01-01'", 'NULL', "'9876'", 'NULL', "'example'", 42, "'2024-07-28T01:23:45.678'", "'2024-07-28T02:34:56.789'", "'2024-07-28T03:45:67.890'", "'user_test'", "'complete'", "'2024-07-28T04:56:78.901'", "'2024-07-28T05:67:89.012'", 'NULL', "'spark-calc-1234-driver'", 'NULL', 'NULL', "'XYZ'"]
[2024-07-29, 22:12:39 UTC] {logging_mixin.py:151} INFO - Original string values_str_3: ['1234', '5678', "'ABC_123'", "'xyz-calc'", "'2024-01-01'", 'NULL', "'9876'", 'NULL', "'example'", '42', "'2024-07-28T01:23:45.678'", "'2024-07-28T02:34:56.789'", "'2024-07-28T03:45:67.890'", "'user_test'", "'complete'", "'2024-07-28T04:56:78.901'", "'2024-07-28T05:67:89.012'", 'NULL', "'spark-calc-1234-driver'", 'NULL', 'NULL', "'XYZ'"]

Are you willing to submit PR?

• Yes I am willing to submit a PR!

Code of Conduct

• I agree to follow this project's Code of Conduct

[boring-cyborg[bot]]

Thanks for opening your first issue here! Be sure to follow the issue template! If you are willing to raise PR to address this issue please do so, no need to wait for approval.

[potiuk]

It's likely your misunderstanding - this is how default log formatter logs strings that have \n character - it prints them as new line. I am not sure what your expectations are, but If you want different formatter - you can configure it using https://airflow.apache.org/docs/apache-airflow/stable/administration-and-deployment/logging-monitoring/advanced-logging-configuration.html - airflow uses standard python logging framework, and exposes a way how you can configure your loggers, filters and formatters - and if you do not like the formatter here, you can change it (for example if you do not want to split lines containing \n in multiple lines you can write your own formatter or find an existing one to print messages containing \n in a single line.

Converted it into a discussion if more is neede.

[potiuk]

Up to you. Again - the easier it gets to reproduce, the higher chance is that somone will look at it.

[artemSSSS]

Here is minimal reproducible example.

values_str_3 = ',\n    '.join(['values_str_3'] * 10)
print(f"values_str_3:\n    {values_str_3}")

[2024-08-04, 08:06:08 UTC] {logging_mixin.py:151} INFO - values_str_3:
    values_str_3,
    values_str_3

It does seem like some kind of deduplication of strings in the logs.
But I can't find a setting in Airflow that controls this so probably it's a bug.

[potiuk]

Can you (and I repeat it for the third time):

• explain what deployment you have, what logging configuration you have and where you see the problem
• provide a drop-in DAG that results in this

Again - your goal is to minimise the time that someone will have to spend on reproducing it so that they can continue diagnosing it, rather than experimenting with snippets of code that you have not explained where you run and in what circumstances and what kind of logging you have configured and you have not explained where you see those errors (UI/ files?) - do you see it in both log file and UI. What deployment you use? What logging you have configured?

All this information will save anyone looking at your problem enormous amount of time having to guess all that - especially that airflow has a very complex logging mechanism, a lot of ways how logs from distributed components are shared with other components and a lot of it depends on the kind of deployment you have and what kind of logging you use.

Yes it is possible. there is a bug or inconsistency in some of those mechanism, but if you provide this information, then it might save a LOT of time for searching for a reason - and minimising that time should be your goal.

Can you please come back with all that information and drop-in DAG that can be used to reproduce the problem following information about your deployment ?

[artemSSSS]

Thank you for your patience. I don't have direct access to the server with Airflow where the error is observed. I didn't set it up and don't know exactly what is there, so I set up a completely new server locally from scratch as described here.

Here is the environment:

Ubuntu 22.04.3 LTS
Airflow version 2.9.3
Python 3.10.12

Here is the test DAG:

from datetime import datetime
from airflow import DAG
from airflow.operators.dummy_operator import DummyOperator
from airflow.operators.python_operator import PythonOperator

def test():
    values_str_3 = ',\n    '.join(['values_str_3'] * 10)
    print(f"values_str_3:\n    {values_str_3}")
    
dag = DAG('test', description='test DAG',
    start_date=datetime(2024, 3, 20), catchup=False)
    
test_operator = PythonOperator(task_id='test_task',
python_callable=test, dag=dag)

test_operator

Here is the incorrect display in the UI:

Meanwhile, everything is displayed correctly in the server logs.

[2024-08-06T03:57:00.303+0400] {taskinstance.py:430} INFO - ::endgroup::
[2024-08-06T03:57:00.304+0400] {logging_mixin.py:188} INFO - values_str_3:
    values_str_3,
    values_str_3,
    values_str_3,
    values_str_3,
    values_str_3,
    values_str_3,
    values_str_3,
    values_str_3,
    values_str_3,
    values_str_3
[2024-08-06T03:57:00.304+0400] {python.py:237} INFO - Done. Returned value was: None

[artemSSSS]

#41346