rb_thread_call_with_gvl error when using send_query with notice_processor pg >= 0.15.0

[ged]

Original report by royaltm NA (Bitbucket: royaltm, GitHub: royaltm).

---

When the notice_processor or notice_receiver is set and when trying to call #send_query which triggers some immediate notice the library crashes with rb_thread_call_with_gvl error.

I've stumbled upon this BUG running regular auto re-connect tests of my gem
with newer (>= 0.15.0) pg.

To run the example below you need to be able to restart the postgres server to trigger the notice. The notice is only triggered when using unix sockets to connect to pg server.

The BUG didn't exist before 0.15.0.

ruby 1.9.3p374
libpq version: 9.0.3

export PGHOST=/tmp
export PGDATABASE=test
export PGDATA=/path/to/your/pgsql/data
irb

gem 'pg', '= 0.15.0'
require 'pg'
puts PG::VERSION
$pgserver_cmd_stop = %Q[sudo su - postgres -c 'pg_ctl stop -m fast']
$pgserver_cmd_start = %Q[sudo su - postgres -c 'pg_ctl -l $PGDATA/postgres.log start -w']
pg=PG::Connection.new
pg.set_notice_processor {|msg| puts "warning from pgsql: #{msg.to_s.chomp.inspect}"}
pg.send_query('SELECT current_timestamp;')
pg.get_last_result.getvalue(0,0)
system($pgserver_cmd_stop);system($pgserver_cmd_start)
pg.send_query('SELECT current_timestamp;')

it will generate [BUG] rb_thread_call_with_gvl: called by a thread which has GVL.
see full trace here

To show that this is exactly the problem with #send_query and message processor below are examples that don't throw the BUG:

The example with message processor but without send_query:

gem 'pg', '= 0.15.0'
require 'pg'
puts PG::VERSION
$pgserver_cmd_stop = %Q[sudo su - postgres -c 'pg_ctl stop -m fast']
$pgserver_cmd_start = %Q[sudo su - postgres -c 'pg_ctl -l $PGDATA/postgres.log start -w']
pg=PG::Connection.new
pg.set_notice_processor {|msg| puts "warning from pgsql: #{msg.to_s.chomp.inspect}"}
pg.query('SELECT current_timestamp;').getvalue(0,0)
system($pgserver_cmd_stop);system($pgserver_cmd_start)
pg.query('SELECT current_timestamp;').getvalue(0,0)

it will generate a regular error as it was supposed to:

warning from pgsql: "FATAL:  terminating connection due to administrator command"
PG::UnableToSend: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.

        from (irb):8:in `exec'
        from (irb):8
        from /usr/local/bin/irb:12:in `<main>'

The example with send_query and without message processor:

gem 'pg', '= 0.15.0'
require 'pg'
puts PG::VERSION
$pgserver_cmd_stop = %Q[sudo su - postgres -c 'pg_ctl stop -m fast']
$pgserver_cmd_start = %Q[sudo su - postgres -c 'pg_ctl -l $PGDATA/postgres.log start -w']
pg=PG::Connection.new
pg.send_query('SELECT current_timestamp;')
pg.get_last_result.getvalue(0,0)
system($pgserver_cmd_stop);system($pgserver_cmd_start)
pg.send_query('SELECT current_timestamp;')

FATAL:  terminating connection due to administrator command
PG::UnableToSend: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.

        from (irb):8:in `send_query'
        from (irb):8
        from /usr/local/bin/irb:12:in `<main>'

[ged]

Original comment by Lars Kanis (Bitbucket: larskanis, GitHub: larskanis).

---

Thank you @royaltm for this great analysis! Fortunately this is quite easy to fix - send_query has to be wrapped by rb_thread_call_without_gvl(). I'll look which other functions could potentially send notifications and would break with this error. It should be easy to verify with your great preparation.

[ged]

Original comment by royaltm NA (Bitbucket: royaltm, GitHub: royaltm).

---

I think all #send_* methods, particularly:

• send_query_prepared
• send_prepare
• send_describe_prepared
• send_describe_portal

will trigger notice in the same way send_query did in the example above:

gem 'pg', '= 0.15.0'
require 'pg'
$pgserver_cmd_stop = %Q[sudo su - postgres -c 'pg_ctl stop -m fast']
$pgserver_cmd_start = %Q[sudo su - postgres -c 'pg_ctl -l $PGDATA/postgres.log start -w']
pg=PG::Connection.new
pg.set_notice_processor {|msg| }
pg.send_prepare('time_now', 'SELECT current_timestamp')
pg.get_last_result
system($pgserver_cmd_stop);system($pgserver_cmd_start)
pg.send_query_prepared('time_now')
# or
pg.send_describe_prepared('time_now')
# or
pg.send_describe_portal('whatever')
# or
pg.send_prepare('one', 'SELECT 1')

[ged]

Original comment by Lars Kanis (Bitbucket: larskanis, GitHub: larskanis).

---

Wrap all PQsend* functions to be called without GVL.

These functions could trigger the notice callback when some notice is yet
in the buffer. The notice callback needs to be called without GVL since it
always reaquires the GLV. This fixes issue #171.