View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000490Pgpool-IIBugpublic2019-04-03 15:232019-08-13 09:01
Reporterzatvobor Assigned Tot-ishii  
PrioritynormalSeveritycrashReproducibilityalways
Status closedResolutionopen 
PlatformkubernetesOSubuntuOS Version14
Product Version4.0.2 
Summary0000490: Child process was terminated after receiving `SYNC` message
Descriptionwe've been using `4.0.2` (`4.0.3` has the same behavior) with enabled `memcached` based query cache. So, after `statement: Execute`, `closing` and finally `syncing` messages the current connection is crashed with message `pid 1: WARNING: child process with pid: 53 was terminated by segmentation fault`.

After turning off `memory_cache_enabled` OR with out final `SYNC` message the issue is not present - the appliance/cached query flow behaves as expected.
Thanks.
Steps To ReproduceSo, here is how to reproduce the issue (based on https://github.com/epgsql/epgsql client):

```
➜ epgsql git:(master) make compile && ./rebar3 shell
===> Verifying dependencies...
===> Compiling epgsql
Erlang/OTP 21 [erts-10.3.1] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [hipe] [dtrace]

Eshell V10.3.1 (abort with ^G)
1> {ok, C} = epgsql:connect("localhost", "postgres", "postgres", #{database =>"localhost"}).
{ok,<0.127.0>}
# 2019-04-02 12:02:45: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relistemp'
# 2019-04-02 12:02:45: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_namespace AS n WHERE c.relname = 'pg_type' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
# 2019-04-02 12:02:45: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: SELECT count(*) from (SELECT has_function_privilege('postgres', 'pg_catalog.to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s
# 2019-04-02 12:02:45: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'
# 2019-04-02 12:02:45: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = pg_catalog.to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
# 2019-04-02 12:02:45: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: SELECT typname::text, oid::int4, typarray::int4 FROM pg_type WHERE typname IN ('geometry','hstore') ORDER BY typname
2> epgsql:parse(C, "statement", "SELECT $1", [int2]).
{ok,{statement,"statement",
               [{column,<<"?column?">>,int2,21,2,-1,1}],
               [int2],
               [{21,int2,false}]}}
# 2019-04-02 12:03:02: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: Parse: SELECT $1
# 2019-04-02 12:03:02: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: D message
3> epgsql:prepared_query(C, "statement", [1]).
{ok,[{column,<<"?column?">>,int2,21,2,-1,1}],[{1}]}
# 2019-04-02 12:04:32: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: D message
# 2019-04-02 12:04:32: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: B message
# 2019-04-02 12:04:32: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: Execute: SELECT $1
# 2019-04-02 12:04:32: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: SELECT oid FROM pg_database WHERE datname = 'localhost'
4> epgsql:prepared_query(C, "statement", [1]).
{ok,[{column,<<"?column?">>,int2,21,2,-1,1}],[{1}]}
# 2019-04-02 12:04:33: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: D message
# 2019-04-02 12:04:33: pid 53: LOG: DB node id: 0 backend pid: 23046 statement: B message
# 2019-04-02 12:04:33: pid 53: LOG: fetch from memory cache
# 2019-04-02 12:04:33: pid 53: DETAIL: query result fetched from cache. statement: SELECT $1 00010001000100000002000100010001
6> epgsql:close(C, statement, "statement").
ok
# 2019-04-02 12:12:58: pid 53: LOG: DB node id: 0 backend pid: 23122 statement: C message
7> epgsql:sync(C).
ok
# 2019-04-02 12:13:38: pid 1: WARNING: child process with pid: 53 was terminated by segmentation fault
# 2019-04-02 12:13:38: pid 1: LOG: fork a new child process with pid: 59
```

TagsNo tags attached.

Activities

t-ishii

2019-04-03 15:39

developer   ~0002505

Can you share Pgpool-II log with log_client_messages = on?

zatvobor

2019-04-03 16:07

reporter   ~0002506

```
> {ok, C} = epgsql:connect("localhost", "postgres", "postgres", #{database =>"localhost",timeout => 4000}), epgsql:parse(C, "statement", "SELECT $1", [int2]), epgsql:prepared_query(C, "statement", [3]), epgsql:close(C, statement, "statement"), epgsql:sync(C).
```

```
2019-04-03 07:03:12: pid 22: LOG: Query message from frontend.
2019-04-03 07:03:12: pid 22: DETAIL: query: "SELECT typname::text, oid::int4, typarray::int4 FROM pg_type WHERE typname IN ('geometry','hstore') ORDER BY typname"
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relistemp'
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_namespace AS n WHERE c.relname = 'pg_type' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: SELECT count(*) from (SELECT has_function_privilege('postgres', 'pg_catalog.to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = pg_catalog.to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: SELECT typname::text, oid::int4, typarray::int4 FROM pg_type WHERE typname IN ('geometry','hstore') ORDER BY typname
2019-04-03 07:03:13: pid 22: LOG: Parse message from frontend.
2019-04-03 07:03:13: pid 22: DETAIL: statement: "statement", query: "SELECT $1"
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: Parse: SELECT $1
2019-04-03 07:03:13: pid 22: LOG: Describe message from frontend.
2019-04-03 07:03:13: pid 22: DETAIL: statement: "statement"
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: D message
2019-04-03 07:03:13: pid 22: LOG: Flush message from frontend.
2019-04-03 07:03:13: pid 22: LOG: Describe message from frontend.
2019-04-03 07:03:13: pid 22: DETAIL: statement: "statement"
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: D message
2019-04-03 07:03:13: pid 22: LOG: Flush message from frontend.
2019-04-03 07:03:13: pid 22: LOG: Bind message from frontend.
2019-04-03 07:03:13: pid 22: DETAIL: portal: "", statement: "statement"
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: B message
2019-04-03 07:03:13: pid 22: LOG: Execute message from frontend.
2019-04-03 07:03:13: pid 22: DETAIL: portal: ""
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: Execute: SELECT $1
2019-04-03 07:03:13: pid 22: LOG: Sync message from frontend.
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: SELECT oid FROM pg_database WHERE datname = 'localhost'
2019-04-03 07:03:13: pid 22: LOG: Close message from frontend.
2019-04-03 07:03:13: pid 22: DETAIL: statement: "statement"
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: C message
2019-04-03 07:03:13: pid 22: LOG: Flush message from frontend.
2019-04-03 07:03:13: pid 22: LOG: Sync message from frontend.
2019-04-03 07:03:13: pid 1: WARNING: child process with pid: 22 was terminated by segmentation fault
2019-04-03 07:03:13: pid 1: LOG: fork a new child process with pid: 40
```

In case, when cache record is already saved, the issue does not exist
(second attempt/the same):

```
> {ok, C} = epgsql:connect("localhost", "postgres", "postgres", #{database =>"localhost",timeout => 4000}), epgsql:parse(C, "statement", "SELECT $1", [int2]), epgsql:prepared_query(C, "statement", [3]), epgsql:close(C, statement, "statement"), epgsql:sync(C).
```

```
2019-04-03 07:05:07: pid 30: LOG: Query message from frontend.
2019-04-03 07:05:07: pid 30: DETAIL: query: "SELECT typname::text, oid::int4, typarray::int4 FROM pg_type WHERE typname IN ('geometry','hstore') ORDER BY typname"
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_attribute AS a WHERE c.relname = 'pg_class' AND a.attrelid = c.oid AND a.attname = 'relistemp'
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: SELECT count(*) FROM pg_catalog.pg_class AS c, pg_namespace AS n WHERE c.relname = 'pg_type' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: SELECT count(*) from (SELECT has_function_privilege('postgres', 'pg_catalog.to_regclass(cstring)', 'execute') WHERE EXISTS(SELECT * FROM pg_catalog.pg_proc AS p WHERE p.proname = 'to_regclass')) AS s
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = 'pg_namespace'
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: SELECT count(*) FROM pg_class AS c, pg_namespace AS n WHERE c.oid = pg_catalog.to_regclass('"pg_type"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: SELECT typname::text, oid::int4, typarray::int4 FROM pg_type WHERE typname IN ('geometry','hstore') ORDER BY typname
2019-04-03 07:05:07: pid 30: LOG: Parse message from frontend.
2019-04-03 07:05:07: pid 30: DETAIL: statement: "statement", query: "SELECT $1"
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: Parse: SELECT $1
2019-04-03 07:05:07: pid 30: LOG: Describe message from frontend.
2019-04-03 07:05:07: pid 30: DETAIL: statement: "statement"
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: D message
2019-04-03 07:05:07: pid 30: LOG: Flush message from frontend.
2019-04-03 07:05:07: pid 30: LOG: Describe message from frontend.
2019-04-03 07:05:07: pid 30: DETAIL: statement: "statement"
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: D message
2019-04-03 07:05:07: pid 30: LOG: Flush message from frontend.
2019-04-03 07:05:07: pid 30: LOG: Bind message from frontend.
2019-04-03 07:05:07: pid 30: DETAIL: portal: "", statement: "statement"
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: B message
2019-04-03 07:05:07: pid 30: LOG: Execute message from frontend.
2019-04-03 07:05:07: pid 30: DETAIL: portal: ""
2019-04-03 07:05:07: pid 30: LOG: fetch from memory cache
2019-04-03 07:05:07: pid 30: DETAIL: query result fetched from cache. statement: SELECT $1 00010001000100000002000300010001
2019-04-03 07:05:07: pid 30: LOG: Sync message from frontend.
2019-04-03 07:05:07: pid 30: LOG: Close message from frontend.
2019-04-03 07:05:07: pid 30: DETAIL: statement: "statement"
2019-04-03 07:05:07: pid 30: LOG: DB node id: 0 backend pid: 32231 statement: C message
2019-04-03 07:05:07: pid 30: LOG: Flush message from frontend.
2019-04-03 07:05:07: pid 30: LOG: Sync message from frontend.
```

t-ishii

2019-04-03 16:43

developer   ~0002507

Hum. It's interesting that 'D' (describe) messages were sent twice.

2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: D message
2019-04-03 07:03:13: pid 22: LOG: Flush message from frontend.
2019-04-03 07:03:13: pid 22: LOG: Describe message from frontend.
2019-04-03 07:03:13: pid 22: DETAIL: statement: "statement"
2019-04-03 07:03:13: pid 22: LOG: DB node id: 0 backend pid: 32215 statement: D message
2019-04-03 07:03:13: pid 22: LOG: Flush message from frontend.

But I think this is a waste of time but should be harmless.

Anyway, I tried to reproduce the problem by using pgproto (https://github.com/tatsuo-ishii/pgproto) because it's very handy.
Unfortunately I have not succeeded yet to reproduce the crash.

zatvobor

2019-04-03 17:17

reporter   ~0002508

first `Describe` issued for `epgsql:parse/4` call and second one for `epgsql:prepared_query/3` (see steps to reproduce it section).

So, I disabled connection to `pgpool` from all our `erlang`/`elixir` projects due to the issue. Once again, the issue was bobbled after turning on `memcached` query cache. With out query cache, those apps (based on `epgsql`, `postgrex` drivers) work well.

t-ishii

2019-04-03 17:26

developer   ~0002509

> first `Describe` issued for `epgsql:parse/4` call and second one for `epgsql:prepared_query/3` (see steps to reproduce it section).
I don't know the internal of epgsql, but apparently those two describe messages are for a named statement "statement" created by the previous parse message:
2019-04-03 07:05:07: pid 30: LOG: Parse message from frontend.
2019-04-03 07:05:07: pid 30: DETAIL: statement: "statement", query: "SELECT $1"

So at least from the wire protocol's point of view, those two describe messages should return identical info.

zatvobor

2019-04-04 00:12

reporter   ~0002514

Let me know what can I do to help you to localize the issue?

t-ishii

2019-04-04 08:06

developer   ~0002515

A gdb back trace when Pgpool-II was crashed is helpful.

t-ishii

2019-05-21 10:14

developer   ~0002608

No response from the reporter over 1 month. I am going to close this issue soon.

zatvobor

2019-05-21 23:26

reporter   ~0002623

OK. I'll reopen it after getting gdb back trace.
The issue is reproduced for me. So, I have to take a time for getting more details for you.
Thanks.

Issue History

Date Modified Username Field Change
2019-04-03 15:23 zatvobor New Issue
2019-04-03 15:38 t-ishii Assigned To => t-ishii
2019-04-03 15:38 t-ishii Status new => assigned
2019-04-03 15:39 t-ishii Note Added: 0002505
2019-04-03 15:40 t-ishii Status assigned => feedback
2019-04-03 16:07 zatvobor Note Added: 0002506
2019-04-03 16:07 zatvobor Status feedback => assigned
2019-04-03 16:43 t-ishii Note Added: 0002507
2019-04-03 17:17 zatvobor Note Added: 0002508
2019-04-03 17:26 t-ishii Note Added: 0002509
2019-04-04 00:12 zatvobor Note Added: 0002514
2019-04-04 08:06 t-ishii Note Added: 0002515
2019-04-04 08:07 t-ishii Status assigned => feedback
2019-05-21 10:14 t-ishii Note Added: 0002608
2019-05-21 23:26 zatvobor Note Added: 0002623
2019-05-21 23:26 zatvobor Status feedback => assigned
2019-08-13 09:01 administrator Status assigned => closed