Question about client_min_messages and SQLSTATE 42000

[rossj-cargotel]

One PostgreSQL 9.5.3...

I have a function I'm working on using The failing query works fine with psql on postgres and sqlcmd on informix.

select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id;

If client_min_messages is set to NOTICE or DEBUG1, I get the following:

postgres@cargotel [local]# select * from quickbooks_sync(' ');
WARNING:  opened informix connection with warnings
DETAIL:  informix SQLSTATE 01I01: "Database has transactions "
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
WARNING:  informix_fdw: could not start transaction: "Syntax error or access violation ", SQLSTATE 42000
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
WARNING:  opened informix connection with warnings
DETAIL:  informix SQLSTATE 01I01: "Database has transactions "
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
WARNING:  informix_fdw: could not start transaction: "Syntax error or access violation ", SQLSTATE 42000
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
 quickbooks_sync
-----------------

(1 row)

Time: 1159.637 ms

If I set client_min_messages to DEBUG2 or greater, the query works just fine:

postgres@cargotel [local]# SET client_min_messages TO DEBUG2;
SET
Time: 0.124 ms
postgres@cargotel [local]#
postgres@cargotel [local]# select * from quickbooks_sync(' ');
DEBUG:  uuid = <PLyResult status=5 nrows=1 rows=[{'split_part': '86e83e43'}]>
CONTEXT:  PL/Python function "quickbooks_sync"
DEBUG:  timestamp = <PLyResult status=5 nrows=1 rows=[{'split_part': '1471018930'}]>
CONTEXT:  PL/Python function "quickbooks_sync"
DEBUG:  txn_id = <PLyResult status=5 nrows=1 rows=[{'split_part': '86e83e43'}]>-<PLyResult status=5 nrows=1 rows=[{'split_part': '1471018930'}]>
CONTEXT:  PL/Python function "quickbooks_sync"
DEBUG:  time_created = <PLyResult status=5 nrows=1 rows=[{'to_char': '2016-08-12T12:22:10-04:00'}]>
CONTEXT:  PL/Python function "quickbooks_sync"
DEBUG:  informix connection dsn "jplm@cargodevnet"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  reusing cached informix connection "nobodyjplmcargodevnet"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
WARNING:  opened informix connection with warnings
DETAIL:  informix SQLSTATE 01I01: "Database has transactions "
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  informix database connection using transactions
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
WARNING:  informix_fdw: could not start transaction: "Syntax error or access violation ", SQLSTATE 42000
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  predicate for pushdown:
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  prepare query "SELECT *, rowid FROM load_trx"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  declare cursor "nobodyjplmcargodevnet_cur4_15"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  informix connection dsn "jplm@cargodevnet"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  reusing cached informix connection "nobodyjplmcargodevnet"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
WARNING:  opened informix connection with warnings
DETAIL:  informix SQLSTATE 01I01: "Database has transactions "
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  informix database connection using transactions
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
WARNING:  informix_fdw: could not start transaction: "Syntax error or access violation ", SQLSTATE 42000
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  predicate for pushdown:
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  prepare query "SELECT *, rowid FROM trxmain_inserts"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  declare cursor "nobodyjplmcargodevnet_cur4_16"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  populate descriptor area for statement "nobodyjplmcargodevnet_stmt4_15"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  get descriptor column count 24
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  open cursor "nobodyjplmcargodevnet_cur4_15"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  populate descriptor area for statement "nobodyjplmcargodevnet_stmt4_16"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  get descriptor column count 2
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  open cursor "nobodyjplmcargodevnet_cur4_16"
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  informix fdw scan end
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  informix fdw scan end
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  informix_fdw: undo declare
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  informix_fdw: undo prepare
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  informix_fdw: undo declare
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  informix_fdw: undo prepare
CONTEXT:  SQL statement "select distinct(load_id) from jplm_dev.load_trx where trxmain_id in (select id from jplm_dev.trxmain_inserts) order by load_id"
PL/Python function "quickbooks_sync"
DEBUG:  Loads = <PLyResult status=5 nrows=33 rows=[{'load_id': 27141}, {'load_id': 27149}, {'load_id': 27391}, {'load_id': 27393}, {'load_id': 27414}, {'load_id': 27436}, {'load_id': 27440}, {'load_id': 27451}, {'load_id': 27452}, {'load_id': 27620}, {'load_id': 27745}, {'load_id': 27764}, {'load_id': 27766}, {'load_id': 28673}, {'load_id': 28839}, {'load_id': 28841}, {'load_id': 28846}, {'load_id': 28847}, {'load_id': 29058}, {'load_id': 29063}, {'load_id': 29064}, {'load_id': 29065}, {'load_id': 29261}, {'load_id': 29262}, {'load_id': 29264}, {'load_id': 29265}, {'load_id': 29266}, {'load_id': 29268}, {'load_id': 29277}, {'load_id': 29278}, {'load_id': 29279}, {'load_id': 29280}, {'load_id': 29586}]>
CONTEXT:  PL/Python function "quickbooks_sync"
LOG:  duration: 1020.693 ms  statement: select * from quickbooks_sync(' ');
 quickbooks_sync
-----------------

(1 row)

Time: 1020.803 ms

For now I'll just set client_min_messages to DEBUG2 but this seems very odd. Jeff