Postgresql – Identify process issuing a query

postgresqlpostgresql-9.6trigger

With this table

                      Table "scheduled_message"
     Column     |           Type           | Collation | Nullable | Default
----------------+--------------------------+-----------+----------+---------
 id             | uuid                     |           | not null |
 recipient_id   | uuid                     |           | not null |
 document       | jsonb                    |           | not null |
 created        | timestamp with time zone |           | not null | now()
 time           | timestamp with time zone |           | not null |
Triggers:
    delete_scheduled_message AFTER DELETE ON scheduled_message FOR EACH ROW EXECUTE PROCEDURE scheduled_message_deleted()
    new_scheduled_message AFTER INSERT ON scheduled_message FOR EACH ROW EXECUTE PROCEDURE message_scheduled()

And this insert trigger

CREATE OR REPLACE FUNCTION message_scheduled() RETURNS TRIGGER AS $message_scheduled$
  BEGIN
    RAISE LOG 'UPDATING NEXT_SCHEDULED FOR RECIPIENT %', NEW.recipient_id;
    UPDATE recipient
    SET next_scheduled = CASE WHEN coalesce(next_scheduled_time, '3000-01-01 12:00:00') > NEW.time AND NEW.time >= CLOCK_TIMESTAMP() - INTERVAL '5 seconds' THEN NEW.id ELSE next_scheduled END,
        next_scheduled_time = CASE WHEN coalesce(next_scheduled_time, '3000-01-01 12:00:00') > NEW.time AND NEW.time >= CLOCK_TIMESTAMP() - INTERVAL '5 seconds' THEN NEW.time ELSE next_scheduled_time END,
        num_scheduled = num_scheduled + 1
    WHERE id = NEW.recipient_id;

    RETURN NULL;
  END;
$message_scheduled$ LANGUAGE plpgsql;

And this delete trigger

CREATE OR REPLACE FUNCTION scheduled_message_deleted() RETURNS TRIGGER AS $scheduled_message_deleted$
  BEGIN
    RAISE LOG 'DELETING FROM SCHEDULED_MESSAGE FOR RECIPIENT %', OLD.recipient_id;
    WITH next_scheduled AS (
      SELECT id, time
      FROM scheduled_message
      WHERE recipient_id = OLD.recipient_id
      AND time >= CLOCK_TIMESTAMP() - INTERVAL '5 seconds'
      ORDER BY time DESC
      LIMIT 1
    )
    UPDATE recipient
    SET next_scheduled = next_scheduled.id,
        next_scheduled_time = next_scheduled.time,
        num_scheduled = num_scheduled - 1
    FROM next_scheduled
    WHERE recipient.id = OLD.recipient_id;

    RETURN NULL;
  END;
$scheduled_message_deleted$ LANGUAGE plpgsql;

When I try to add a scheduled message via my application, the logs report that rows are being deleted rom the scheduled_message table. I can see the output of the RAISE LOG statement in the scheduled_message_deleted trigger function.

example logs

api-db_1                      | LOG:  DELETING FROM SCHEDULED_MESSAGE FOR RECIPIENT 4c2b5ea8-4892-4e2a-8b7e-2efc81f067e5
api-db_1                      | CONTEXT:  PL/pgSQL function scheduled_message_deleted() line 3 at RAISE
api-db_1                      | STATEMENT:  delete from scheduled_message where recipient_id = $1
api-db_1                      | LOG:  DELETING FROM SCHEDULED_MESSAGE FOR RECIPIENT 4c2b5ea8-4892-4e2a-8b7e-2efc81f067e5
api-db_1                      | CONTEXT:  PL/pgSQL function scheduled_message_deleted() line 3 at RAISE
api-db_1                      | STATEMENT:  delete from scheduled_message where recipient_id = $1
api-db_1                      | LOG:  UPDATING NEXT_SCHEDULED FOR RECIPIENT 4c2b5ea8-4892-4e2a-8b7e-2efc81f067e5
api-db_1                      | CONTEXT:  PL/pgSQL function message_scheduled() line 20 at RAISE
api-db_1                      | STATEMENT:  insert into scheduled_message("id","program_id","recipient_id","time","document") values (...),(...),(...)
api-db_1                      |
api-db_1                      | LOG:  UPDATING NEXT_SCHEDULED FOR RECIPIENT 4c2b5ea8-4892-4e2a-8b7e-2efc81f067e5
api-db_1                      | CONTEXT:  PL/pgSQL function message_scheduled() line 20 at RAISE
api-db_1                      | STATEMENT:  insert into scheduled_message("id","program_id","participant_id","document") values (...),(...),(...)
api-db_1                      |
api-db_1                      | LOG:  UPDATING NEXT_SCHEDULED FOR RECIPIENT 4c2b5ea8-4892-4e2a-8b7e-2efc81f067e5
api-db_1                      | CONTEXT:  PL/pgSQL function message_scheduled() line 20 at RAISE
api-db_1                      | STATEMENT:  insert into scheduled_message("id","program_id","participant_id","document") values (...),(...),(...)
api-db_1                      |
api-db_1                      | LOG:  UPDATING NEXT_SCHEDULED FOR RECIPIENT 4c2b5ea8-4892-4e2a-8b7e-2efc81f067e5
api-db_1                      | CONTEXT:  PL/pgSQL function message_scheduled() line 20 at RAISE
api-db_1                      | STATEMENT:  insert into scheduled_message("id","program_id","participant_id","document") values (...),(...),(...)

Unfortunately, I am not expecting rows to be deleted as a result adding scheduled messages. I looked through all the functions in my database, and sql in my application and cannot figure out where the statement delete from scheduled_message where recipient_id = $1 is coming from.

Deleting all old rows, and inserting all new ones for each add operation is very inefficient, but that is how the operation was originally written. I'm trying to fix this in my application code, I thought I removed the logic from my code & database, but we can see the problem is still happening. It's not obvious where, and I am hopeful someone can help me debug the issue so I can find what's calling the delete & insert code

I tried performing the steps in my application and immediately running pg_stat_activity but the delete statement isn't in the proc output.

My question is how can I find the client that is issuing the delete statement? pg_stat_activity provides the client's ip address which would be very helpful, but i'm not able to catch the delete statement in that output.

Are there other tools or tricks I can use to figure out what is issuing this statement?

Best Answer

Have the remote host added to the RAISE LOG message, by putting %h into log_line_prefix. (Maybe add some other fields as well, like user and application name.)