View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000546 | Pgpool-II | Bug | public | 2019-09-11 22:49 | 2019-10-31 18:40 |
| Reporter | venkat_rj | Assigned To | t-ishii | ||
| Priority | high | Severity | block | Reproducibility | always |
| Status | resolved | Resolution | open | ||
| Platform | Linux | OS | REHL7/CentOS | OS Version | 7.5.1804 |
| Product Version | 4.0.6 | ||||
| Target Version | 4.0.7 | Fixed in Version | 4.0.7 | ||
| Summary | 0000546: Executing DML & DDL combination via PostgresSQL ODBC to pgpool fails with 'WARNING: child process with pid: 24870 was terminated | ||||
| Description | Executing DML & DDL combination via PostgresSQL ODBC to pgpool fails with 'WARNING: child process with pid: 24870 was terminated by segmentation fault' By defult we config pgpool's load_balance_mode is off. Looks like pgpool is doing load balance when it sees SELECT statement even though load_balance_mode is off. ================================== Version: ================================== - pgpool-II version 4.0.6 - postgres (PostgreSQL) 11.5 - PostgresSQL psqlodbc-11.01.0000 ================================== pgpool erorr in the log file: ================================== 2019-09-10 10:22:09: pid 20205: LOG: fork a new child process with pid: 24870 2019-09-10 10:22:18: pid 24870: LOG: pool_send_and_wait: Error or notice message from backend: : DB node id: 0 backend pid: 24885 statement: "CREATE INDEX "USERS_AUTH_ID_INDEX" ON "ENTITIES" ( "AUTH_ID" )" message: "relation "USERS_AUTH_ID_INDEX" already exists" 2019-09-10 10:22:18: pid 20205: WARNING: child process with pid: 24870 was terminated by segmentation fault 2019-09-10 10:22:18: pid 20205: LOG: fork a new child process with pid: 24888 2019-09-10 10:22:18: pid 19153: WARNING: ssl read: EOF detected 2019-09-10 10:22:18: pid 19153: ERROR: unable to read data from frontend 2019-09-10 10:22:18: pid 19153: DETAIL: socket read failed with an error "Success" ================================== pgpool.conf: ================================== egrep -i 'load|white|black' pgpool.conf # Whitespace may be used. Comments are introduced with "#" anywhere on a line. # server for the changes to take effect, or use "pgpool reload". Some # Weight for backend 0 (only in load balancing mode) # load_balance_mode. # LOAD BALANCING MODE load_balance_mode = on # Activate load balancing mode ignore_leading_white_space = on # Ignore leading white spaces of each query white_function_list = '' black_function_list = 'currval,lastval,nextval,setval' black_query_pattern_list = '' # if on, ignore SQL comments when judging if load balance or disable_load_balance_on_write = 'transaction' # Load balance behavior when write query is issued # subsequent read queries will not be load balanced # will not be load balanced until the session ends. # not be load balanced until the session ends. # thus increases load of master. # thus increases load of master. white_memqcache_table_list = '' black_memqcache_table_list = '' load_balance_mode = off # Added through Consul-template ========================================================================= DML & DDL Calls via PostgresSQL ODBC driver to pgpool summary: ========================================================================= In: ConnectionHandle=0x7fffea45b960, WindowHandle=0, InConnectionString=`tracefile=/tmp/fun.croc;traceflags=319;CONOPTS=(SSLMode=require;pqopt={sslrootcert=/opt/<MaskedPath>/cacerts/trustedcerts.pem});DRIVER=POSTGRES;CATALOG=FB;DATABASE='DA_SYSCAT_default';;UID=dbmsowner;PWD=<Removed>;SERVER=cole-test2-onpremnnnnn.com;PORT=5431`, StringLength1=TKTS_NTS, OutConnectionString=0, BufferLength=0, StringLength2Ptr=0, DriverCompletion=TKTS_DRIVER_NOPROMPT=0 In: StatementHandle=0x7fffea494640, Sql=`SET SESSION CLIENT_MIN_MESSAGES=WARNING;`, SqlL=40 In: StatementHandle=0x7fffea494640, Sql=`CREATE SCHEMA IF NOT EXISTS "FS_SYSCAT";`, SqlL=41 In: StatementHandle=0x7fffea494640, Sql=`SET SCHEMA 'FS_SYSCAT';`, SqlL=23 In: ConnectionHandle=0x7fffdfd9a8e0, WindowHandle=0, InConnectionString=`tracefile=/tmp/fun.croc;traceflags=319;CONOPTS=(SSLMode=require;pqopt={sslrootcert=/opt/<MaskedPath>/cacerts/trustedcerts.pem});DRIVER=POSTGRES;CATALOG=FB;DATABASE='DA_SYSCAT_default';;UID=dbmsowner;PWD=<Removed>;SERVER=cole-test2-onpremnnnnn.com;PORT=5431`, StringLength1=TKTS_NTS, OutConnectionString=0, BufferLength=0, StringLength2Ptr=0, DriverCompletion=TKTS_DRIVER_NOPROMPT=0 In: StatementHandle=0x7fffdfd9e0e0, Sql=`SET SESSION CLIENT_MIN_MESSAGES=WARNING;`, SqlL=40 In: StatementHandle=0x7fffdfd9e0e0, Sql=`SET SCHEMA 'FS_SYSCAT';`, SqlL=23 In: StatementHandle=0x7fffdfd9e0e0, Sql=`select "VERSION" from "DATA_SERVICES" where "DS_ID"=1`, SqlL=53 In: StatementHandle=0x7fffdfd9e0e0, Sql=`SELECT * FROM "DATA_SERVICES" WHERE 1=0`, SqlL=39 In: StatementHandle=0x7fffdfd9e0e0, Sql=`CREATE INDEX "USERS_AUTH_ID_INDEX" ON "ENTITIES" ( "AUTH_ID" )`, SqlL=62 In: StatementHandle=0x7fffdfd9e0e0, Sql=`CREATE INDEX "USERS_ENTITY_ID_INDEX" ON "ENTITIES" ( "ENTITY_ID" )`, SqlL=66 ================== ODBC log: ================== # Processing input file `/home/centos/t9.croc` TKTSAllocHandle: In: HandleType = TKTS_HANDLE_ENV=1, InputHandle = TKTS Extension Handle=0x7f04341645c0, OutputHandlePtr = VALID Return: TKTS_SUCCESS = 0 Out: *OutputHandlePtr = henv1=0x7f043417a0a0 TKTSAllocHandle: In: HandleType = TKTS_HANDLE_DBC=2, InputHandle = henv1=0x7f043417a0a0, OutputHandlePtr = VALID Return: TKTS_SUCCESS = 0 Out: *OutputHandlePtr = hdbc1=0x7f043417c940 TKTSDriverConnect: In: ConnectionHandle = hdbc1=0x7f043417c940, WindowHandle = TKTS_NULL_HANDLE=0, InConnectionstring = `tracefile=/tmp/fun.croc;traceflags=319;CONOPTS=(SSLMode=require;pqopt={sslrootcert=/opt/<MaskedPath>/cacerts/trustedcerts.pem});DRIVER=POSTGRES;CATALOG=FB;DATABASE='DA_SYSCAT_default';;UID=dbmsowner;PWD=<Removed>;SERVER=cole-test2-onpremnnnnn.com;PORT=5431`, StringLength1 = TKTS_NTS=-3, OutConnectionString = NULL=0, BufferLength = 0, StringLength2Ptr = NULL=0, DriverCompletion = TKTS_DRIVER_NOPROMPT=0 Return: TKTS_SUCCESS_WITH_INFO = 0x80fff801 dbc: szSqlState = `01S02`, *pfNativeError = -2130708291, *pcbErrorMsg = 25 MessageText = `Current catalog set to FB` TKTSSetConnectAttr: In: ConnectionHandle = hdbc1=0x7f043417c940, Attribute = TKTS_ATTR_AUTOCOMMIT=102, ValuePtr = TKTS_AUTOCOMMIT_ON=1, StringLength = TKTS_IS_UINTEGER=-5 Return: TKTS_SUCCESS = 0 TKTSAllocHandle: In: HandleType = TKTS_HANDLE_STMT=3, InputHandle = hdbc1=0x7f043417c940, OutputHandlePtr = VALID Return: TKTS_SUCCESS = 0 Out: *OutputHandlePtr = hstmt1=0x7f0425306c00 TKTSExecDirect: In: StatementHandle = hstmt1=0x7f0425306c00, StatementText = `SET SESSION CLIENT_MIN_MESSAGES=WARNING;`, TextLength = 40 Return: TKTS_SUCCESS = 0 TKTSExecDirect: In: StatementHandle = hstmt1=0x7f0425306c00, StatementText = `CREATE SCHEMA IF NOT EXISTS "FS_SYSCAT";`, TextLength = 41 Return: TKTS_SUCCESS = 0 TKTSExecDirect: In: StatementHandle = hstmt1=0x7f0425306c00, StatementText = `SET SCHEMA 'FS_SYSCAT';`, TextLength = 23 Return: TKTS_SUCCESS = 0 TKTSFreeHandle: In: HandleType = TKTS_HANDLE_STMT=3, Handle = hstmt1=0x7f0425306c00 Return: TKTS_SUCCESS = 0 TKTSAllocHandle: In: HandleType = TKTS_HANDLE_DBC=2, InputHandle = henv1=0x7f043417a0a0, OutputHandlePtr = VALID Return: TKTS_SUCCESS = 0 Out: *OutputHandlePtr = hdbc2=0x7f04253070e0 TKTSGetConnectAttr: In: ConnectionHandle = hdbc2=0x7f04253070e0, Attribute = <unknown>=20000, ValuePtr = VALID, BufferLength = TKTS_IS_POINTER=-4, StringLengthPtr = VALID Return: TKTS_SUCCESS = 0 Out: *ValuePtr = 0, *StringLengthPtr = 8 TKTSDriverConnect: In: ConnectionHandle = hdbc2=0x7f04253070e0, WindowHandle = TKTS_NULL_HANDLE=0, InConnectionstring = `tracefile=/tmp/fun.croc;traceflags=319;CONOPTS=(SSLMode=require;pqopt={sslrootcert=/opt/<MaskedPath>/cacerts/trustedcerts.pem});DRIVER=POSTGRES;CATALOG=FB;DATABASE='DA_SYSCAT_default';;UID=dbmsowner;PWD=<Removed>;SERVER=cole-test2-onpremnnnnn.com;PORT=5431`, StringLength1 = TKTS_NTS=-3, OutConnectionString = NULL=0, BufferLength = 0, StringLength2Ptr = NULL=0, DriverCompletion = TKTS_DRIVER_NOPROMPT=0 Return: TKTS_SUCCESS_WITH_INFO = 0x80fff801 dbc: szSqlState = `01S02`, *pfNativeError = -2130708291, *pcbErrorMsg = 25 MessageText = `Current catalog set to FB` TKTSSetConnectAttr: In: ConnectionHandle = hdbc2=0x7f04253070e0, Attribute = TKTS_ATTR_AUTOCOMMIT=102, ValuePtr = TKTS_AUTOCOMMIT_ON=1, StringLength = TKTS_IS_UINTEGER=-5 Return: TKTS_SUCCESS = 0 TKTSAllocHandle: In: HandleType = TKTS_HANDLE_STMT=3, InputHandle = hdbc2=0x7f04253070e0, OutputHandlePtr = VALID Return: TKTS_SUCCESS = 0 Out: *OutputHandlePtr = hstmt2=0x7f0425311d00 TKTSExecDirect: In: StatementHandle = hstmt2=0x7f0425311d00, StatementText = `SET SESSION CLIENT_MIN_MESSAGES=WARNING;`, TextLength = 40 Return: TKTS_SUCCESS = 0 TKTSExecDirect: In: StatementHandle = hstmt2=0x7f0425311d00, StatementText = `SET SCHEMA 'FS_SYSCAT';`, TextLength = 23 Return: TKTS_SUCCESS = 0 TKTSFreeHandle: In: HandleType = TKTS_HANDLE_STMT=3, Handle = hstmt2=0x7f0425311d00 Return: TKTS_SUCCESS = 0 TKTSAllocHandle: In: HandleType = TKTS_HANDLE_STMT=3, InputHandle = hdbc1=0x7f043417c940, OutputHandlePtr = VALID Return: TKTS_SUCCESS = 0 Out: *OutputHandlePtr = hstmt3=0x7f0425311d00 TKTSFreeStmt: In: StatementHandle = hstmt3=0x7f0425311d00, Option = TKTS_CLOSE=0 Return: TKTS_SUCCESS = 0 TKTSExecDirect: In: StatementHandle = hstmt3=0x7f0425311d00, StatementText = `select "VERSION" from "DATA_SERVICES" where "DS_ID"=1`, TextLength = 53 Return: TKTS_SUCCESS = 0 TKTSBindCol: In: StatementHandle = hstmt3=0x7f0425311d00, ColumnNumber = 1, TargetType = TKTS_C_TKCHAR=3, TargetValuePtr = VALID, BufferLength = 1024, StrLen_or_IndPtr = VALID Return: TKTS_SUCCESS = 0 TKTSFetch: In: StatementHandle = hstmt3=0x7f0425311d00 Return: TKTS_SUCCESS = 0 TKTSFreeStmt: In: StatementHandle = hstmt3=0x7f0425311d00, Option = TKTS_CLOSE=0 Return: TKTS_SUCCESS = 0 TKTSFreeHandle: In: HandleType = TKTS_HANDLE_STMT=3, Handle = hstmt3=0x7f0425311d00 Return: TKTS_SUCCESS = 0 TKTSAllocHandle: In: HandleType = TKTS_HANDLE_STMT=3, InputHandle = hdbc1=0x7f043417c940, OutputHandlePtr = VALID Return: TKTS_SUCCESS = 0 Out: *OutputHandlePtr = hstmt4=0x7f041b49e6a0 TKTSPrepare: In: StatementHandle = hstmt4=0x7f041b49e6a0, StatementText = `SELECT * FROM "DATA_SERVICES" WHERE 1=0`, TextLength = 39 Return: TKTS_SUCCESS = 0 TKTSFreeStmt: In: StatementHandle = hstmt4=0x7f041b49e6a0, Option = TKTS_UNPREPARE=101 Return: TKTS_SUCCESS = 0 TKTSExecDirect: In: StatementHandle = hstmt4=0x7f041b49e6a0, StatementText = `CREATE INDEX "USERS_AUTH_ID_INDEX" ON "ENTITIES" ( "AUTH_ID" )`, TextLength = 62 Return: TKTS_ERROR = 0x80fff802 stmt: szSqlState = `42P07`, *pfNativeError = 1, *pcbErrorMsg = 92, *ColumnNumber = -2, *RowNumber = 0 MessageText = `ERROR: ERROR: relation "USERS_AUTH_ID_INDEX" already exists; Error while executing the query` TKTSExecDirect: In: StatementHandle = hstmt4=0x7f041b49e6a0, StatementText = `CREATE INDEX "USERS_ENTITY_ID_INDEX" ON "ENTITIES" ( "ENTITY_ID" )`, TextLength = 66 Return: TKTS_ERROR = 0x80fff802 stmt: szSqlState = `08S01`, *pfNativeError = 35, *pcbErrorMsg = 174, *ColumnNumber = -2, *RowNumber = 0 MessageText = `ERROR: server closed the connection unexpectedly This probably means the server terminated abnormally before or while processing the request. ; The connection has been lost` TKTSFreeHandle: In: HandleType = TKTS_HANDLE_STMT=3, Handle = hstmt4=0x7f041b49e6a0 Return: TKTS_SUCCESS = 0 TKTSEndTran: In: HandleType = TKTS_HANDLE_DBC=2, Handle = hdbc1=0x7f043417c940, CompletionType = TKTS_ROLLBACK=1 Return: TKTS_SUCCESS = 0 # Done! ================================== Wrokaround: ================================== Reason is when we pass a hint i.e. /*NO LOAD BALANCE*/ with SELECT statement pgpool dose not terminate child process with segmentation fault. But without the hint it dose fail. ================================== SELECT with Hint: ================================== TKTSPrepare: In: StatementHandle = hstmt4=0x7fd050948d00, StatementText = `/*NO LOAD BALANCE*/ SELECT * FROM "DATA`, TextLength = 39 | ||||
| Tags | No tags attached. | ||||
|
|
Please provide stack trace of the process terminated by segfault. Also I need pgpool log enabling log_client_messages. > Looks like pgpool is doing load balance when it sees SELECT statement even though load_balance_mode is off. Please provide whole pgpool.con. At least you need to provide master_slave_mode and master_slave_sub_mode. |
|
|
|
|
|
Uploaded pgpool_20190912_155329.log and pgpool.conf. Unfortunately current pgpool RPM we build in house dose not have debugging symbols. We are trying to build one. I will try to generate the the stack trace once I install the debug enabled RPM. Attaching the gdb_pgpool_pid_attach.log |
|
|
Thanks. pgpool_20190912_155329.log is very helpful. I am going to inspect the log file so that I can create a minimum set of test case using pgproto (pgproto is a small tool included in the Pgpool-II source code to replay messages, provided in a text file, between client and pgpool [1]). [1] https://www.pgpool.net/docs/latest/en/html/pgproto.html |
|
|
I found the cause of the segfault. Following is a minimum test case for this: 1. Parse (SELECT 1) to statement foo 2. DEALLOCATE foo 3. Error query (for example CREATE INDEX on already existing index) At 3, data created at 1 is already removed. However, it forgot to set the state and after 3, pgpool tries to remove the data which is already removed. Also I found occasional hang while processing above sequence if load balance is enabled. I have commited/pushed fix for both to all supported branches. For 4.0 stable branches see the commits for more details: https://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=a333a454d6881d380e330cbb85aa9ef02d912631 https://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=83c1988d3c8bdd0ecbdf6a3d28371febee556483 |
|
|
Thank you so much for fixing the issue and I appreciate your valuable time. |
|
|
For reference, I set following log parameters to generate the pgpool log file. log_client_messages = on log_statement = on log_error_verbosity = verbose # terse, default, or verbose messages log_min_messages = debug5 # values in order of decreasing detail: |
|
|
With new code build fails with below error. Please can you help. Build log file: pgpool_build_full_log.txt Build error: 2019-09-16T14:57:57.034308000Z context/pool_query_context.c: In function 'where_to_send_deallocate': 2019-09-16T14:57:57.034383000Z context/pool_query_context.c:1487: error: 'POOL_QUERY_CONTEXT' has no member named 'load_balance_node_id' 2019-09-16T14:57:57.034404000Z context/pool_query_context.c:1487: error: 'POOL_QUERY_CONTEXT' has no member named 'load_balance_node_id' 2019-09-16T14:57:57.048176000Z make[2]: *** [context/pool_query_context.o] Error 1 2019-09-16T14:57:57.048270000Z make[2]: *** Waiting for unfinished jobs.... 2019-09-16T14:57:57.378666000Z make[2]: Leaving directory `/build/BUILD/sas-pgpool-II-4.0.6/src' 2019-09-16T14:57:57.379245000Z make[1]: *** [all-recursive] Error 1 2019-09-16T14:57:57.379321000Z make[1]: Leaving directory `/build/BUILD/sas-pgpool-II-4.0.6/src' 2019-09-16T14:57:57.379921000Z make: *** [all-recursive] Error 1 2019-09-16T14:57:57.380335000Z error: Bad exit status from /var/tmp/rpm-tmp.1km5xn (%build) 2019-09-16T14:57:57.380395000Z 2019-09-16T14:57:57.380418000Z 2019-09-16T14:57:57.380432000Z RPM build errors: 2019-09-16T14:57:57.380447000Z Bad exit status from /var/tmp/rpm-tmp.1km5xn (%build) 2019-09-16T14:57:57.410413000Z pralixx.builder:[ERROR] Error occurred during execution of 'build' method 2019-09-16T14:57:57.426527000Z error: exit status 1 2019-09-16T14:57:57.748756134Z job 01DMX97PVEAFQQ5E0HP121WV61 "sas-pgpool-II-40-4.0.6-20190916.1568645534833" failed: job exited with status 1 |
|
|
Sorry, https://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=83c1988d3c8bdd0ecbdf6a3d28371febee556483 was not needed for 4.0 stable or older branches. The commit has been reverted for those older branches. |
|
|
Thank you so much. We tested our code with new fix and it worked. |
|
|
Thank you for your report! Issue resolved. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2019-09-11 22:49 | venkat_rj | New Issue | |
| 2019-09-12 07:30 | t-ishii | Note Added: 0002834 | |
| 2019-09-12 07:31 | t-ishii | Assigned To | => t-ishii |
| 2019-09-12 07:31 | t-ishii | Status | new => feedback |
| 2019-09-13 05:10 | venkat_rj | File Added: pgpool.conf | |
| 2019-09-13 05:10 | venkat_rj | File Added: pgpool_20190912_155329.log | |
| 2019-09-13 05:20 | venkat_rj | File Added: gdb_pgpool_pid_attach.log | |
| 2019-09-13 05:20 | venkat_rj | Note Added: 0002843 | |
| 2019-09-13 05:20 | venkat_rj | Status | feedback => assigned |
| 2019-09-13 08:50 | t-ishii | Note Added: 0002844 | |
| 2019-09-16 10:38 | t-ishii | Note Added: 0002849 | |
| 2019-09-16 10:38 | t-ishii | Status | assigned => feedback |
| 2019-09-17 00:23 | venkat_rj | Note Added: 0002850 | |
| 2019-09-17 00:23 | venkat_rj | Status | feedback => assigned |
| 2019-09-17 00:30 | venkat_rj | Note Added: 0002851 | |
| 2019-09-17 04:09 | venkat_rj | File Added: pgpool_build_full_log.txt | |
| 2019-09-17 04:09 | venkat_rj | Note Added: 0002852 | |
| 2019-09-17 07:41 | t-ishii | Note Added: 0002854 | |
| 2019-09-17 15:39 | t-ishii | Status | assigned => feedback |
| 2019-09-18 23:35 | venkat_rj | Note Added: 0002861 | |
| 2019-09-18 23:35 | venkat_rj | Status | feedback => assigned |
| 2019-09-19 07:29 | t-ishii | Status | assigned => resolved |
| 2019-09-19 07:29 | t-ishii | Target Version | => 4.0.7 |
| 2019-09-19 11:50 | administrator | Note Added: 0002863 | |
| 2019-10-31 18:40 | administrator | Fixed in Version | => 4.0.7 |
