rb_thread_call_with_gvl error when using send_query with notice_processor pg >= 0.15.0

Issue #171 resolved
royaltm NA
created an issue

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>'

Comments (4)

  1. Lars Kanis

    Thank you @royaltm NA 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.

  2. royaltm NA reporter

    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')
    
  3. Lars Kanis

    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.

    → <<cset 1fd77c0a4cea>>

  4. Log in to comment