Operator SQLExecuteQueryOperator not logging RAISE NOTICE statements in PostgreSQL functions

[hpereira98]

Apache Airflow Provider(s)

postgres

Versions of Apache Airflow Providers

apache-airflow-providers-postgres==5.7.1

Apache Airflow version

2.9.1

Operating System

Linux

Deployment

Other 3rd-party Helm chart

Deployment details

Airflow deployed in remote K8s cluster and locally using a Minikube cluster.

PostgreSQL version: 10.15.

What happened

We've upgraded our Airflow instance from 1.10.12 to 2.9.1.
We were previously using PostgresOperator to trigger the execution of a few PostgreSQL functions, which had RAISE NOTICE statements to print some important information regarding the functions execution.
In the previous version we were using, we could see those logs in the Web UI,
However, after the upgrade, we stopped seeing these.
We've tried:

• configuring client_min_messages and log_min_messages to NOTICE in the database level;
• changing PostgresOperator to the new SQLExecuteQueryOperator;
• setting the operator's parameter show_return_value_in_logs to true.
  None of these seem to allow these logs being shown.

What you think should happen instead

RAISE NOTICE statements should be shown in the DAGs logs.

How to reproduce

1. Set up Airflow instance with version 1.10.12.
2. Create Dummy DAG that triggers a PostgreSQL function with a RAISE NOTICE statement.
3. See logs printed in the Web UI for that DAG execution.
4. Upgrade Airflow to 2.9.1.
5. Trigger same DAG.
6. Stop seeing the same logs printed in the Web UI.

Database preparation statements:

CREATE TABLE test (
  value int
);

INSERT INTO test (value)
VALUES (1);

Example function:

CREATE OR REPLACE FUNCTION update_function()
RETURNS void AS
  $$
    DECLARE
      query text;
      affected_rows numeric;
      ts timestamp;
      result text;
    BEGIN
      SET SESSION TIME ZONE 'UTC';
      ts = clock_timestamp();

      UPDATE test
      SET value = 2
      WHERE value = 1;

      GET DIAGNOSTICS affected_rows = ROW_COUNT;

      SELECT format('affected: %s (%s)', affected_rows, age(clock_timestamp(), ts))
      INTO result;

      RAISE NOTICE '%', result;

    END;
 $$
LANGUAGE PLPGSQL SECURITY DEFINER;

Example DAG:

dag = DAG(
    "run-update-function",
    schedule_interval="* * * * *",  # runs every minute
    catchup=False,
)

update_function = SQLExecuteQueryOperator(
    task_id="update_function",
    dag=dag,
    conn_id="my-postgresql-database",
    sql="SELECT update_function();",
)

Anything else

This was also reported by another Airflow user in https://stackoverflow.com/questions/77913339/how-do-i-print-raise-notice-from-postgresql-in-airflow-logs.

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

[potiuk]

If someone would like to investigate it, I marked it as good first issue.

[potiuk]

BTW. It would be great for somoeone who might want to look at it, if you posted example of the functions and how you are calling them @hpereira98 - otherwise it might be difficult for them to investigate it. The more information and reproduciblitly you provide, the more likely someone will be interested in fixing it.

[hpereira98]

Added example function and DAG!

[potiuk]

For anyone who would like to implement it (maybe you @hpereira98 ? This is the most certain way to get it done, otherwise it will have to wait for someone who will volunteer to implement it): it seems that in order to implement it one would have to print notices from the connection https://stackoverflow.com/questions/50274199/python2-print-postgresql-stored-procedure-raise-notice .

[hpereira98]

The weird thing is that they were being printed in the version we were using previously (1.10.12), but not in the new one. Are you aware of any major changes made to the mechanism used in the PostgreSQL operators?

[potiuk]

The weird thing is that they were being printed in the version we were using previously (1.10.12), but not in the new one. Are you aware of any major changes made to the mechanism used in the PostgreSQL operators?

Well Airflow 1.10 is end of life for more than 3 years - this is when all users were supposed to migrate and nobody remembers anything that was there (there were probablly 10.000 or so changes and no backwards compatibility even expected for 1.10. If you had migrated back then probably you would find someone who would know somothing, but being 3 years late with the migration does not help. You can take a look at release notes since then or code changes (probably few thousands of entries) and see if you can find somethign because what's written in the release notes is the best trace of what had happend between the 3 years untouched version and now.

At this stage this is a feature to be implemented, not even a bug, and even if it were classified as a bug it falls into "hopefully someone will pick an interest and implement it" - this is a free open-source software and comes "as is" and generally a lot of people contribute what they need if it is missing. If you are in a hurry and do not want to wait for someone to show up - the most certain way to get something like that is to roll sleeves up and do it (or find someone who is more able if you don't feel like doing it yourself).

[dondaum]

In 1.10.12 the postgres operator logged all notices after running the sql command. I think this happens here.

In newer provider versions this changed.

I can have a look at it and see if and how we could enable or at least optional enable it.

[potiuk]

I can have a look at it and see if and how we could enable or at least optional enable it.

PRs to add it back are always most welcome

[dondaum]

Sure. Please assign it to me. Happy to help here.

[potiuk]

Cool :)