Thread: dblink: could not send query: another command is already in progress
Hi all
I try to use dblink to create a asynchronous logging facility. I have
the following code
-- open the dblink if it does not yet exist
V_DBLINK_CONNECTION_NAME :=
GET_PROPERTY_VALUE_STRING(
I_PROPERTY_NAME => 'DBLINK_CONNECTION_NAME'
);
select dblink_get_connections() into V_DBLINK_CONNECTION_NAMES;
if (
V_DBLINK_CONNECTION_NAMES is null
or V_DBLINK_CONNECTION_NAME != any(V_DBLINK_CONNECTION_NAMES)
) then
V_DBLINK_CONNECT_STRING :=
GET_PROPERTY_VALUE_STRING(
I_PROPERTY_NAME => 'DBLINK_CONNECT_STRING'
);
-- better to use dblink_connect_u with password file?
perform dblink_connect(
V_DBLINK_CONNECTION_NAME,
V_DBLINK_CONNECT_STRING
);
end if;
-- send query asynchronously
-- Use literal (%L) as it returns the value null as the
unquoted
-- string NULL.
V_QUERY := format(
$s$select true $s$ || C_LB ||
$s$ from %I( $s$ || C_LB ||
$s$ I_FUNCTION => %L, $s$ || C_LB ||
$s$ I_MESSAGE => %L, $s$ || C_LB ||
$s$ I_LEVEL => %L, $s$ || C_LB ||
$s$ I_PRESENT_USER => %L, $s$ || C_LB ||
$s$ I_SESSION_USER => %L, $s$ || C_LB ||
$s$ I_TRANSACTION_TIMESTAMP => $s$ ||
$s$ %L::timestamp, $s$ || C_LB ||
$s$ I_TRANSACTION_ID => $s$ ||
$s$ %L::bigint, $s$ || C_LB ||
$s$ I_SERVER_PID => $s$ ||
$s$ %L::bigint, $s$ || C_LB ||
$s$ I_REMOTE_ADDRESS => $s$ ||
$s$ %L::inet, $s$ || C_LB ||
$s$ I_REMOTE_PORT => $s$ ||
$s$ %L::bigint $s$ || C_LB ||
$s$ ); $s$ || C_LB ||
$s$commit $s$,
'WRITE_MESSAGE_TO_TABLE',
C_CALLER_FUNCTION,
I_MESSAGE,
I_LEVEL,
C_PRESENT_USER,
C_SESSION_USER,
C_TRANSACTION_TIMESTAMP,
C_TRANSACTION_ID,
C_SERVER_PID,
C_REMOTE_ADDRESS,
C_REMOTE_PORT
);
-- send query when connection is ready
V_WAIT_FOR :=
GET_PROPERTY_VALUE_INTERVAL(
I_PROPERTY_NAME => 'BUSY_WAIT_INTERVAL'
); -- to avoid continuous re-querying, already queried here
-- surprisingly, dblink_is_busy does not return boolean,
but 0 for
-- false
while dblink_is_busy(V_DBLINK_CONNECTION_NAME) != 0 loop
perform pg_sleep_for(V_WAIT_FOR);
end loop;
perform dblink_send_query(
V_DBLINK_CONNECTION_NAME,
V_QUERY
);
raise notice 'Connection busy: %', dblink_is_busy(V_DBLINK_CONNECTION_NAME);
raise notice 'Last error: %',
dblink_error_message(V_DBLINK_CONNECTION_NAME);
raise notice 'Cancel query: %',
dblink_cancel_query(V_DBLINK_CONNECTION_NAME);
-- ??? commit needed?
raise notice 'Connection busy: %', dblink_is_busy(V_DBLINK_CONNECTION_NAME);
while dblink_is_busy(V_DBLINK_CONNECTION_NAME) != 0 loop
perform pg_sleep_for(V_WAIT_FOR);
raise notice 'Waited for commit for % seconds', V_WAIT_FOR;
raise notice 'Connection busy: %', dblink_is_busy(V_DBLINK_CONNECTION_NAME);
end loop;
perform dblink_send_query(
V_DBLINK_CONNECTION_NAME,
'commit'
);
I get the following output.
psql:testing/test.pg_sql:41: NOTICE: Connection busy: 1
psql:testing/test.pg_sql:41: NOTICE: Last error: OK
psql:testing/test.pg_sql:41: NOTICE: Cancel query: OK
psql:testing/test.pg_sql:41: NOTICE: Connection busy: 0
psql:testing/test.pg_sql:41: NOTICE: could not send query: another
command is already in progress
I did all the raise notice and dblink querying and cancelling to get
some information on what is going on but I am no wiser than before as
without that the connection was not busy either. But it was still
blocking I had the second call even though the commit did not seem to
work and I was trying to send it for good. Btw, there is no entry in the
logging table which is being done when the same function is called
without using dblink.
Maybe I am wrong but I tried the solution with dblink_connect
dblink_send_query instead of simply dblink believing that dblink
function would open and close a connection at every call. I wanted to
avoid this overhead.
Has anyone an idea?
--
SIP/iptel.org: thiemo.kellner
Öffentlicher PGP-Schlüssel:
http://pgp.mit.edu/pks/lookup?op=get&search=0xCA167FB0E717AFFC
Attachment
Thiemo Kellner wrote: > I try to use dblink to create a asynchronous logging facility. I have > the following code > > [...] > perform dblink_send_query( > V_DBLINK_CONNECTION_NAME, > V_QUERY > ); > raise notice 'Connection busy: %', dblink_is_busy(V_DBLINK_CONNECTION_NAME); > raise notice 'Last error: %', > dblink_error_message(V_DBLINK_CONNECTION_NAME); > raise notice 'Cancel query: %', > dblink_cancel_query(V_DBLINK_CONNECTION_NAME); > -- ??? commit needed? > raise notice 'Connection busy: %', dblink_is_busy(V_DBLINK_CONNECTION_NAME); > while dblink_is_busy(V_DBLINK_CONNECTION_NAME) != 0 loop > perform pg_sleep_for(V_WAIT_FOR); > raise notice 'Waited for commit for % seconds', V_WAIT_FOR; > raise notice 'Connection busy: %', dblink_is_busy(V_DBLINK_CONNECTION_NAME); > end loop; > perform dblink_send_query( > V_DBLINK_CONNECTION_NAME, > 'commit' > ); > > I get the following output. > psql:testing/test.pg_sql:41: NOTICE: Connection busy: 1 > > psql:testing/test.pg_sql:41: NOTICE: Last error: OK > > psql:testing/test.pg_sql:41: NOTICE: Cancel query: OK > > psql:testing/test.pg_sql:41: NOTICE: Connection busy: 0 > > psql:testing/test.pg_sql:41: NOTICE: could not send query: another > command is already in progress > Has anyone an idea? The cause of the error message is clear; as the documentation says: dblink_cancel_query attempts to cancel any query that is in progress on the named connection. Note that this is not certain to succeed (since, for example, the remote query might already have finished). A cancel request simply improves the odds that the query will fail soon. You must still complete the normal query protocol, for example by calling dblink_get_result. Not sure if that answers all your questions. Yours, Laurenz Albe -- Cybertec | https://www.cybertec-postgresql.com
On 03/30/18 07:39, Laurenz Albe wrote: >> psql:testing/test.pg_sql:41: NOTICE: Connection busy: 1 >> >> psql:testing/test.pg_sql:41: NOTICE: Last error: OK >> >> psql:testing/test.pg_sql:41: NOTICE: Cancel query: OK >> >> psql:testing/test.pg_sql:41: NOTICE: Connection busy: 0 >> >> psql:testing/test.pg_sql:41: NOTICE: could not send query: another >> command is already in progress > >> Has anyone an idea? > > The cause of the error message is clear; as the documentation says: Not to me. As mentioned in my first post, originally I did no cancelling and error checking and had the same error. Trying to cancelling did not alter behaviour. It boils down to: Why do I get the "another command is already in progress" when dblink_is_busy acknowledges the dblink to not be busy by returning 0? > the query will fail soon. You must still complete the normal query protocol, > for example by calling dblink_get_result. Ah, maybe this is the underlying problem. If dblink requires that results get retrieved by dblink_get_result before the dblink is actually ready to receive another query, it would explain the error I get. However, I feel than the result of dblink_is_busy is faulty, counter-intuitive or just useless in that context. Or I just misinterpreted documentation: "checks if connection is busy with an async query" My understand there is that the actual query is still being processed, the gathering of the results. I did not count the keeping of the result as part of the query. I hope I can check on that today and get back with my findings. -- SIP/iptel.org: thiemo.kellner Öffentlicher PGP-Schlüssel: http://pgp.mit.edu/pks/lookup?op=get&search=0xCA167FB0E717AFFC
Attachment
Thiemo Kellner wrote: > The cause of the error message is clear; as the documentation says: > > > the query will fail soon. You must still complete the normal query protocol, > > for example by calling dblink_get_result. > > Ah, maybe this is the underlying problem. If dblink requires that > results get retrieved by dblink_get_result before the dblink is actually > ready to receive another query, it would explain the error I get. > However, I feel than the result of dblink_is_busy is faulty, > counter-intuitive or just useless in that context. Or I just > misinterpreted documentation: "checks if connection is busy with an > async query" > > My understand there is that the actual query is still being processed, > the gathering of the results. I did not count the keeping of the result > as part of the query. That is a misunderstanding. If the connection is "busy", that means that the asynchronous query is still busy receiving a result from the server. Once it is no longer busy, a result has arrived and is ready to be consumed. You have to consume the result before you can send the next query. Yours, Laurenz Albe -- Cybertec | https://www.cybertec-postgresql.com
On 03/30/18 11:14, Laurenz Albe wrote: > You have to consume the result before you can send the next query. I changed implementation but still get the same error but now different context. I tried to retrieve the result but I failed I committed the last code to its project repository at SourceForge https://sourceforge.net/p/pglogger/code/HEAD/tree/ and put the code to pastebin.com Test calls: https://pastebin.com/xfUp9NAL function WRITE_MESSAGE: https://pastebin.com/LDjE0Czx function WRITE_MESSAGE_TO_TABLE: https://pastebin.com/vkBkehZF Output psql:testing/test.pg_sql:41: NOTICE: 2018-03-30 18:41:18.245592 - Calling function: - Current user: act - Session user: act - Transaction timestamp: 2018-03-30 18:41:18.240580 - Transaction ID: - Server process ID: 22401 - Address of the remote connection: - Port of the remote connection: - Message: Test WRITE_MESSAGE write_message --------------- (1 row) psql:testing/test.pg_sql:42: NOTICE: 2018-03-30 18:41:18.257750 - Calling function: - Current user: act - Session user: act - Transaction timestamp: 2018-03-30 18:41:18.240580 - Transaction ID: - Server process ID: 22401 - Address of the remote connection: - Port of the remote connection: - Message: Test WRITE_MESSAGE 2nd call psql:testing/test.pg_sql:42: ERROR: function WRITE_MESSAGE_TO_TABLE(i_function => text, i_message => text, i_level => text, i_present_user => name, i_session_user => name, i_transaction_timestamp => timestamp with time zone, i_transaction_id => bigint, i_server_pid => bigint, i_remote_address => inet, i_remote_port => integer) does not exist HINT: No function matches the given name and argument types. You might need to add explicit type casts. CONTEXT: Error occurred on dblink connection named "PGLOGGER_CONNECTION": could not execute query. SQL statement "SELECT * from dblink_get_result(V_DBLINK_CONNECTION_NAME) as t(ID bigint)" PL/pgSQL function write_message(text,text) line 126 at PERFORM psql:testing/test.pg_sql:42: STATEMENT: select WRITE_MESSAGE('Test WRITE_MESSAGE 2nd call', 'NOTICE'); -- SIP/iptel.org: thiemo.kellner Öffentlicher PGP-Schlüssel: http://pgp.mit.edu/pks/lookup?op=get&search=0xCA167FB0E717AFFC
Attachment
Thiemo Kellner wrote: > On 03/30/18 11:14, Laurenz Albe wrote: > > You have to consume the result before you can send the next query. > > I changed implementation but still get the same error but now different > context. I tried to retrieve the result but I failed > > I committed the last code to its project repository at SourceForge > https://sourceforge.net/p/pglogger/code/HEAD/tree/ > > and put the code to pastebin.com > Test calls: https://pastebin.com/xfUp9NAL > function WRITE_MESSAGE: https://pastebin.com/LDjE0Czx > function WRITE_MESSAGE_TO_TABLE: https://pastebin.com/vkBkehZF > > [...] > psql:testing/test.pg_sql:42: ERROR: function > WRITE_MESSAGE_TO_TABLE(i_function => text, i_message => text, i_level => > text, i_present_user => name, i_session_user => name, > i_transaction_timestamp => timestamp with time zone, i_transaction_id => > bigint, i_server_pid => bigint, i_remote_address => inet, i_remote_port > => integer) does not exist > HINT: No function matches the given name and argument types. You might > need to add explicit type casts. > CONTEXT: Error occurred on dblink connection named > "PGLOGGER_CONNECTION": could not execute query. > SQL statement "SELECT * from > dblink_get_result(V_DBLINK_CONNECTION_NAME) as t(ID bigint)" > PL/pgSQL function write_message(text,text) line 126 at PERFORM > psql:testing/test.pg_sql:42: STATEMENT: select WRITE_MESSAGE('Test > WRITE_MESSAGE 2nd call', 'NOTICE'); I couldn't dig through all your code, but two things seemed suspicious: > if ( > V_DBLINK_CONNECTION_NAMES is null > or V_DBLINK_CONNECTION_NAME != any(V_DBLINK_CONNECTION_NAMES) I don't think you want "!=ANY" there. Shouldn't that be "<>ALL" ? "<>ANY" will *always* be true if there are at least two different entries. The other thing is that you seem to call "dblink_get_result" on any existing connection before use. But you can only call the function if there is a result outstanding. One of your error messages above seems to suggest that this is your problem. Yours, Laurenz Albe -- Cybertec | https://www.cybertec-postgresql.com
On 04/03/18 11:28, Laurenz Albe wrote:
>> [...]
>> psql:testing/test.pg_sql:42: ERROR: function
>> WRITE_MESSAGE_TO_TABLE(i_function => text, i_message => text, i_level =>
>> text, i_present_user => name, i_session_user => name,
>> i_transaction_timestamp => timestamp with time zone, i_transaction_id =>
>> bigint, i_server_pid => bigint, i_remote_address => inet, i_remote_port
>> => integer) does not exist
>> HINT: No function matches the given name and argument types. You might
>> need to add explicit type casts.
>> CONTEXT: Error occurred on dblink connection named
>> "PGLOGGER_CONNECTION": could not execute query.
>> SQL statement "SELECT * from
>> dblink_get_result(V_DBLINK_CONNECTION_NAME) as t(ID bigint)"
>> PL/pgSQL function write_message(text,text) line 126 at PERFORM
>> psql:testing/test.pg_sql:42: STATEMENT: select WRITE_MESSAGE('Test
>> WRITE_MESSAGE 2nd call', 'NOTICE');
>
> I couldn't dig through all your code, but two things seemed suspicious:
Thanks for looking into all the same.
>> if (
>> V_DBLINK_CONNECTION_NAMES is null
>> or V_DBLINK_CONNECTION_NAME != any(V_DBLINK_CONNECTION_NAMES)
>
> I don't think you want "!=ANY" there. Shouldn't that be "<>ALL" ?
> "<>ANY" will *always* be true if there are at least two different entries.
In my simple test it works as expected with respect to that. But I did
use it the wrong way as I thought that ! would invert the result of the
any operation as a whole. I changed it to != all but the error persists.
> The other thing is that you seem to call "dblink_get_result" on any existing
> connection before use. But you can only call the function if there is a
> result outstanding.
I call dblink_get_result only if I do not open a dblink connection, i.
e. only on second and following function calls. I put more notice output
into the code showing that dblink_send_query has been called once before
the first call of dblink_get_result. I changed my query to reflect
return bigint value of the called function write_message_to_table. Error
persists.
I put a new pastebin https://pastebin.com/7R45R7qK and committed the
changes.
--
+49 (0)1578-772 37 37
+41 (0)78 947 36 21
SIP/iptel.org: thiemo.kellner
Öffentlicher PGP-Schlüssel:
http://pgp.mit.edu/pks/lookup?op=get&search=0xCA167FB0E717AFFC
Attachment
Thiemo Kellner wrote: > > The other thing is that you seem to call "dblink_get_result" on any existing > > connection before use. But you can only call the function if there is a > > result outstanding. > > I call dblink_get_result only if I do not open a dblink connection, i. > e. only on second and following function calls. I put more notice output > into the code showing that dblink_send_query has been called once before > the first call of dblink_get_result. I changed my query to reflect > return bigint value of the called function write_message_to_table. Error > persists. That's not going to work. You can only call dblink_get_result if there is an outstanding result. You cannot call it on an idle connection, that will cause an error. You should write your code so that whenever dblink_send_query has been called, you also call dblink_get_result, regardless if the query has been cancelled or not, so that you always leave the connection in the "ready for query" state. Then you don't have to clean up. Of course you could also ignore the error you get on dblink_get_result, but that is ugly. Yours, Laurenz Albe -- Cybertec | https://www.cybertec-postgresql.com