Improve error logging in DbtLocalBaseOperator

[davidsteinar]

Improve error logging when the dbt command returns a non-zero exit code. Instead of raising an AirflowException with the full output, log the output using the logger and then raise the exception with a concise error message. This makes the dbt output more readable and not in a single line.

Description

AirflowException logs message in a single line, can be very long.

Related Issue(s)

closes #1003

Breaking Change?

No

[netlify]

✅ Deploy Preview for sunny-pastelito-5ecb04 canceled.

Name	Link
🔨 Latest commit	7e558f6
🔍 Latest deploy log	https://app.netlify.com/sites/sunny-pastelito-5ecb04/deploys/6659a069d7717100088ee2dc

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 95.69%. Comparing base (712ef7d) to head (7e558f6).

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #1004      +/-   ##
==========================================
+ Coverage   95.65%   95.69%   +0.03%     
==========================================
  Files          60       60              
  Lines        2925     2926       +1     
==========================================
+ Hits         2798     2800       +2     
+ Misses        127      126       -1     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[tatiana]

This looks much better, @davidsteinar , thanks a lot for the contribution!

Is there any chance we could add a test to make sure this improvement continues working as expected in the future?

[davidsteinar]

@tatiana something like this?

def test_handle_exception_subprocess():
    """
    Test the handle_exception_subprocess method of the DbtLocalBaseOperator class.
    """
    operator = DbtLocalBaseOperator(profile_config=None)
    result = FullOutputSubprocessResult(exit_code=1, output="test", full_output=["n" * n for n in range(1, 1000)])
    
    # Test when exit_code is non-zero
    with pytest.raises(AirflowException) as err_context:
        operator.handle_exception_subprocess(result)

    assert len(err_context.value) < 100 # Ensure the error message is not too long

[tatiana]

@tatiana something like this?

def test_handle_exception_subprocess():
    """
    Test the handle_exception_subprocess method of the DbtLocalBaseOperator class.
    """
    operator = DbtLocalBaseOperator(profile_config=None)
    result = FullOutputSubprocessResult(exit_code=1, output="test", full_output=["n" * n for n in range(1, 1000)])
    
    # Test when exit_code is non-zero
    with pytest.raises(AirflowException) as err_context:
        operator.handle_exception_subprocess(result)

    assert len(err_context.value) < 100 # Ensure the error message is not too long

Hi @davidsteinar I think you're in the right path - thank you!

The one thing that could be improved is to use perhaps pytest caplog fixture (more info) and check the actual log message, confirming the new behaviour.

Example:

astronomer-cosmos/tests/test_cache.py

Line 76 in cb2a27a

def test__copy_partial_parse_to_project_msg_fails_msgpack(mock_unpack, tmp_path, caplog):

[davidsteinar]

hi again @tatiana , better?

def test_handle_exception_subprocess(caplog):
    """
    Test the handle_exception_subprocess method of the DbtLocalBaseOperator class.
    """
    operator = DbtLocalBaseOperator(profile_config=None)
    result = FullOutputSubprocessResult(exit_code=1, output="test", full_output=["n" * n for n in range(1, 1000)])
    
    caplog.set_level(logging.ERROR)
    # Test when exit_code is non-zero
    with pytest.raises(AirflowException) as err_context:
        operator.handle_exception_subprocess(result)
    assert len(str(err_context.value)) < 100 # Ensure the error message is not too long
    assert len(caplog.text) > 1000 # Ensure the log message is not truncated

[tatiana]

Thanks, @davidsteinar , it's looking good. Could you please add it to:
https://github.com/astronomer/astronomer-cosmos/blob/main/tests/operators/test_local.py?

Once the tests are passing, we can merge this PR! Thanks a lot for your contribution.

[pankajkoti]

Looks like unfortunately there is a minor conflict with main in the file tests/operators/test_local.py. Could you please resolve the conflict and push the commit :) ?

[davidsteinar]

Hi @pankajkoti , I fixed the conflict and a few small things to make the test run , all checks have passed now

[pankajkoti]

Thank you @davidsteinar for improving the exception and error logging. Appreciate the contribution and quick fixes 👏🏽

PR looks good to me. I'm going ahead with the merge

cc: @tatiana