New event that stop debezium task and terminate all Database connection.

[Adrien Quentin]

Hello,

I'm trying to use debezium with postgres in production env. Except postgres, all product is running on docker, using debezium images.

debezium is able to take the initial snapshot successfully, and wait for event.

Doing an event on the targeted table, cause debezium stop his task and postgres database close all connection.

Below the debezium log : 

2017-11-14 12:55:39,337 INFO   ||  Finished WorkerSourceTask{id=inventory-connector-0} commitOffsets successfully in 3 ms   [org.apache.kafka.connect.runtime.WorkerSourceTask]

2017-11-14 13:02:34,156 WARN   Postgres|dbz|records-stream-producer  Closing replication stream due to db connection IO exception...   [io.debezium.connector.postgresql.RecordsStreamProducer]

2017-11-14 13:02:34,161 ERROR  ||  Task inventory-connector-0 threw an uncaught and unrecoverable exception   [org.apache.kafka.connect.runtime.WorkerTask]

org.apache.kafka.connect.errors.ConnectException: org.postgresql.util.PSQLException: Database connection failed when reading from copy

        at io.debezium.connector.postgresql.PostgresConnectorTask.poll(PostgresConnectorTask.java:165)

        at org.apache.kafka.connect.runtime.WorkerSourceTask.execute(WorkerSourceTask.java:163)

        at org.apache.kafka.connect.runtime.WorkerTask.doRun(WorkerTask.java:146)

        at org.apache.kafka.connect.runtime.WorkerTask.run(WorkerTask.java:190)

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

        at java.util.concurrent.FutureTask.run(FutureTask.java:266)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

        at java.lang.Thread.run(Thread.java:748)

Caused by: org.postgresql.util.PSQLException: Database connection failed when reading from copy

        at org.postgresql.core.v3.QueryExecutorImpl.readFromCopy(QueryExecutorImpl.java:964)

        at org.postgresql.core.v3.CopyDualImpl.readFromCopy(CopyDualImpl.java:41)

        at org.postgresql.core.v3.replication.V3PGReplicationStream.receiveNextData(V3PGReplicationStream.java:145)

        at org.postgresql.core.v3.replication.V3PGReplicationStream.readInternal(V3PGReplicationStream.java:114)

        at org.postgresql.core.v3.replication.V3PGReplicationStream.read(V3PGReplicationStream.java:60)

        at io.debezium.connector.postgresql.connection.PostgresReplicationConnection$1.read(PostgresReplicationConnection.java:176)

        at io.debezium.connector.postgresql.RecordsStreamProducer.streamChanges(RecordsStreamProducer.java:112)

        at io.debezium.connector.postgresql.RecordsStreamProducer.lambda$start$1(RecordsStreamProducer.java:98)

        ... 5 more

Caused by: java.io.EOFException

        at org.postgresql.core.PGStream.receiveChar(PGStream.java:284)

        at org.postgresql.core.v3.QueryExecutorImpl.processCopyResults(QueryExecutorImpl.java:1006)

        at org.postgresql.core.v3.QueryExecutorImpl.readFromCopy(QueryExecutorImpl.java:962)

        ... 12 more

2017-11-14 13:02:34,162 ERROR  ||  Task is being killed and will not recover until manually restarted   [org.apache.kafka.connect.runtime.WorkerTask]

below the database log: 

LOG:  exported logical decoding snapshot: "0016F9CA-1" with 0 transaction IDs

LOG:  starting logical decoding for slot "debezium"

DETAIL:  streaming transactions committing after 27/BB682DE8, reading WAL from 27/BB682DB0

LOG:  logical decoding found consistent point at 27/BB682DB0

DETAIL:  There are no running transactions.

LOG:  server process (PID 12388) was terminated by signal 11: Segmentation fault

LOG:  terminating any other active server processes

WARNING:  terminating connection because of crash of another server process

DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.

HINT:  In a moment you should be able to reconnect to the database and repeat your command.

I checked that decoderbufs work well using usage purpose in readme.md from github: https://github.com/debezium/postgres-decoderbufs => everything's ok.

Do you have any idea of this problem ?

thank you.

[Gunnar Morling]

Hi,

This one sounds suspicious:

> WARNING:  terminating connection because of crash of another server process

> DETAIL:  The postmaster has commanded this server process to roll back the

> current transaction and exit, because another server process exited abnormally

> and possibly corrupted shared memory.

Do you find anything more on that in the DB logs? Does it work if you restart the connector?

--Gunnar

[Manabu Kamimura]

Hello,

Thank you for developing Debezium. It is very interesting with capturing changes on databases.

May I ask whether this issue is already fixed?

I am facing at a similar issue with postgresql(9.6.13) and Debezium(0.9.5) on CentOS 7.

(postgresql server is terminated by segmentation fault)

Any kind of information is appreciated.

(Which i should check.)

Best Regards,

Manabu Kamimura

Gunnar Morling:

[Jiri Pechanec]

Could you please try if the issue is present with wal2json too? Also it would be really helpful if you could identify which event is causing the segfault.

[Manabu Kamimura]

Thank you for your response.

The issue is not present with wal2json in my environment. (segfault is not occuring with wal2json).

It is working fine and I am able to capture the change data of the source DB(PostgreSQL).

(I tried by dropping the slot for decoderbuf (using pg_drop_replication_slot) and connect the wal2json plugin.)

When I come back to decodebuf, the issue is present. (segfault occurs with decoderbuf.)

I am not sure which event is causing the issue. I hope the following information may help. 

It occurs when the database is updated (or inserted).

The following is the database log(pg_log) around the segfault. 

(Sorry the locale is in Japanese but I hope you can find anything useful)

Once the segfault occurs, it always occurs when I reconnect the debezium connector.

< 2019-06-13 13:34:40.595 JST > DEBUG:  CommitTransactionCommand

< 2019-06-13 13:34:40.595 JST > DEBUG:  Adding typemodifier 'bigint' for column 0, optional false

< 2019-06-13 13:34:40.595 JST > コンテキスト:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/733C720

< 2019-06-13 13:34:40.595 JST > DEBUG:  Adding typemodifier 'character varying(10)' for column 1, optional false

< 2019-06-13 13:34:40.595 JST > コンテキスト:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/733C720

< 2019-06-13 13:34:40.595 JST > DEBUG:  Adding typemodifier 'date' for column 2, optional false

< 2019-06-13 13:34:40.595 JST > コンテキスト:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/733C720

< 2019-06-13 13:34:40.595 JST > DEBUG:  Adding typemodifier 'integer' for column 3, optional false

< 2019-06-13 13:34:40.595 JST > コンテキスト:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/733C720

< 2019-06-13 13:34:40.595 JST > DEBUG:  Adding typemodifier 'timestamp without time zone' for column 4, optional false

< 2019-06-13 13:34:40.595 JST > コンテキスト:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/733C720

< 2019-06-13 13:34:40.595 JST > DEBUG:  Adding typemodifier 'character varying(50)' for column 5, optional false

< 2019-06-13 13:34:40.595 JST > コンテキスト:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/733C720

< 2019-06-13 13:34:40.595 JST > DEBUG:  Adding typemodifier 'timestamp without time zone' for column 6, optional false

< 2019-06-13 13:34:40.595 JST > コンテキスト:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/733C720

< 2019-06-13 13:34:40.595 JST > DEBUG:  Adding typemodifier 'character varying(50)' for column 7, optional false

< 2019-06-13 13:34:40.595 JST > コンテキスト:  slot "debezium", output plugin "decoderbufs", in the change callback, associated LSN 0/733C720

< 2019-06-13 13:34:40.596 JST > DEBUG:  解析 S_2: ROLLBACK

< 2019-06-13 13:34:40.596 JST > ステートメント:  ROLLBACK

< 2019-06-13 13:34:40.596 JST > DEBUG:  StartTransactionCommand

< 2019-06-13 13:34:40.596 JST > ステートメント:  ROLLBACK

< 2019-06-13 13:34:40.596 JST > LOG:  期間: 0.020 ミリ秒  解析S_2 : ROLLBACK

< 2019-06-13 13:34:40.596 JST > DEBUG:  バインド<unnamed>: S_2

< 2019-06-13 13:34:40.596 JST > LOG:  期間: 0.009 ミリ秒  バインド S_2: ROLLBACK

< 2019-06-13 13:34:40.596 JST > DEBUG:  ProcessUtility

< 2019-06-13 13:34:40.596 JST > ステートメント:  ROLLBACK

< 2019-06-13 13:34:40.596 JST > DEBUG:  CommitTransactionCommand

< 2019-06-13 13:34:40.596 JST > ステートメント:  ROLLBACK

< 2019-06-13 13:34:40.596 JST > LOG:  期間: 0.014 ミリ秒  実行 S_2: ROLLBACK

< 2019-06-13 13:34:40.596 JST > DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make

< 2019-06-13 13:34:40.596 JST > DEBUG:  shmem_exit(0): 6 on_shmem_exit callbacks to make

< 2019-06-13 13:34:40.596 JST > DEBUG:  proc_exit(0): 3 callbacks to make

< 2019-06-13 13:34:40.596 JST > DEBUG:  exit(0)

< 2019-06-13 13:34:40.596 JST > DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make

< 2019-06-13 13:34:40.596 JST > DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make

< 2019-06-13 13:34:40.596 JST > DEBUG:  proc_exit(-1): 0 callbacks to make

< 2019-06-13 13:34:40.597 JST > DEBUG:  reaping dead processes

< 2019-06-13 13:34:40.597 JST > DEBUG:  サーバプロセス (PID 21705)は終了コード0で終了しました

< 2019-06-13 13:34:41.120 JST > DEBUG:  reaping dead processes

< 2019-06-13 13:34:41.120 JST > DEBUG:  サーバプロセス (PID 21662)はシグナル11で終了しました: Segmentation fault

< 2019-06-13 13:34:41.120 JST > LOG:  サーバプロセス (PID 21662)はシグナル11で終了しました: Segmentation fault

< 2019-06-13 13:34:41.120 JST > LOG:  他の活動中のサーバプロセスを終了しています

Best Regards,

Manabu Kamimura

2019年6月12日水曜日 16時07分40秒 UTC+9 Jiri Pechanec:

[Jiri Pechanec]

Hi,

is it possible you can have geometry/geography ralted event and that you have postgis installed?

J.

[Manabu Kamimura]

Hi, 

The postgis I installed is the following. (the output \dx and the postgis_version())

 postgis | 2.4.7      | public     | PostGIS geometry, geography, and raster spa

 POSTGIS="2.4.7 r17330" PGSQL="96" GEOS="3.7.1-CAPI-1.11.1 27a5e771" PROJ="Rel. 4.9.3, 15 August 2016" GDAL="GDAL 2.3.2, released 2018/09/21" LIBXML=

"2.9.1" LIBJSON="0.11" RASTER

I am sorry I don't have any geometry/geographic event as I only installed postgis to use debezium.

The original system does not have postgis.

Best Regards,

Manabu Kamimura

2019年6月13日木曜日 18時30分26秒 UTC+9 Jiri Pechanec:

[Jiri Pechanec]

Hi,

please check https://issues.jboss.org/browse/DBZ-1144

J.

[Manabu Kamimura]

Hi, 

Thank you for taking time for this issue. 

I am not sure yet but maybe I failed to install the postgis properly.

When I tried the following command, I got error. (I tried your command on your post.)

CREATE TABLE public.postgis_table (pk SERIAL, p postgis.GEOMETRY(POINT,3187), ml postgis.GEOGRAPHY(MULTILINESTRING), PRIMARY KEY(pk));

The error says 

ERROR: the type postgis.geometry does not exists.

Best Regards,

Manabu Kamimura

2019年6月14日金曜日 18時10分28秒 UTC+9 Jiri Pechanec:

[Jiri Pechanec]

Your output of the \dx command says that postgis is intalled in public schema not postgis schema. And that's the trigger for the refreneced issue.

J.

[Manabu Kamimura]

I tried with the public schema. The statement worked and the record was inserted (without crash).

INSERT INTO public.postgis_table (p, ml)  VALUES ('SRID=3187;POINT(174.9479 -36.7208)'::geometry, 'MULTILINESTRING((169.1321 -44.7032, 167.8974 -44.6414))'::geography)

Sorry I am working with the application not created by me,  so currently I cannot specify which event is causing the crash.

Manabu Kamimura

2019年6月17日月曜日 12時22分50秒 UTC+9 Jiri Pechanec:

[Jiri Pechanec]

Hi,

thnaks. Could you please try also a table with postgres type point column and try to stream the message from it?

J.

[Manabu Kamimura]

Hi, 

I tried the following command. (It can be executed without crash(segfault)).

CREATE TEMP TABLE x(p point) ;

INSERT INTO x VALUES ('(1,2)');

INSERT INTO x VALUES (point(3, 4));

SELECT * FROM x ;

I put the watcher and got the following as output, so it seems it is working.

null {"schema":{"type":"struct","fields":[{"type":"struct","fields":[{"type":"struct","fields":[{"type":"double","optional":false,"field":"x"},{"type":"double","optional":false,"field":"y"},{"type":"bytes","optional":true,"field":"wkb"},{"type":"int32","optional":true,"field":"srid"}],"optional":true,"name":"io.debezium.data.geometry.Point","version":1,"doc":"Geometry (POINT)","field":"p"}],"optional":true,"name":"dbserver3.public.x.Value","field":"before"},{"type":"struct","fields":[{"type":"struct","fields":[{"type":"double","optional":false,"field":"x"},{"type":"double","optional":false,"field":"y"},{"type":"bytes","optional":true,"field":"wkb"},{"type":"int32","optional":true,"field":"srid"}],"optional":true,"name":"io.debezium.data.geometry.Point","version":1,"doc":"Geometry (POINT)","field":"p"}],"optional":true,"name":"dbserver3.public.x.Value","field":"after"},{"type":"struct","fields":[{"type":"string","optional":true,"field":"version"},{"type":"string","optional":true,"field":"connector"},{"type":"string","optional":false,"field":"name"},{"type":"string","optional":false,"field":"db"},{"type":"int64","optional":true,"field":"ts_usec"},{"type":"int64","optional":true,"field":"txId"},{"type":"int64","optional":true,"field":"lsn"},{"type":"string","optional":true,"field":"schema"},{"type":"string","optional":true,"field":"table"},{"type":"boolean","optional":true,"default":false,"field":"snapshot"},{"type":"boolean","optional":true,"field":"last_snapshot_record"},{"type":"int64","optional":true,"field":"xmin"}],"optional":false,"name":"io.debezium.connector.postgresql.Source","field":"source"},{"type":"string","optional":false,"field":"op"},{"type":"int64","optional":true,"field":"ts_ms"}],"optional":false,"name":"dbserver3.public.x.Envelope"},"payload":{"before":null,"after":{"p":{"x":1.0,"y":2.0,"wkb":"AQEAAAAAAAAAAADwPwAAAAAAAABA","srid":null}},"source":{"version":"0.9.5.Final","connector":"postgresql","name":"dbserver3","db":"test","ts_usec":1560855538546000,"txId":7877,"lsn":142534576,"schema":"public","table":"x","snapshot":true,"last_snapshot_record":false,"xmin":null},"op":"r","ts_ms":1560855538547}}

null {"schema":{"type":"struct","fields":[{"type":"struct","fields":[{"type":"struct","fields":[{"type":"double","optional":false,"field":"x"},{"type":"double","optional":false,"field":"y"},{"type":"bytes","optional":true,"field":"wkb"},{"type":"int32","optional":true,"field":"srid"}],"optional":true,"name":"io.debezium.data.geometry.Point","version":1,"doc":"Geometry (POINT)","field":"p"}],"optional":true,"name":"dbserver3.public.x.Value","field":"before"},{"type":"struct","fields":[{"type":"struct","fields":[{"type":"double","optional":false,"field":"x"},{"type":"double","optional":false,"field":"y"},{"type":"bytes","optional":true,"field":"wkb"},{"type":"int32","optional":true,"field":"srid"}],"optional":true,"name":"io.debezium.data.geometry.Point","version":1,"doc":"Geometry (POINT)","field":"p"}],"optional":true,"name":"dbserver3.public.x.Value","field":"after"},{"type":"struct","fields":[{"type":"string","optional":true,"field":"version"},{"type":"string","optional":true,"field":"connector"},{"type":"string","optional":false,"field":"name"},{"type":"string","optional":false,"field":"db"},{"type":"int64","optional":true,"field":"ts_usec"},{"type":"int64","optional":true,"field":"txId"},{"type":"int64","optional":true,"field":"lsn"},{"type":"string","optional":true,"field":"schema"},{"type":"string","optional":true,"field":"table"},{"type":"boolean","optional":true,"default":false,"field":"snapshot"},{"type":"boolean","optional":true,"field":"last_snapshot_record"},{"type":"int64","optional":true,"field":"xmin"}],"optional":false,"name":"io.debezium.connector.postgresql.Source","field":"source"},{"type":"string","optional":false,"field":"op"},{"type":"int64","optional":true,"field":"ts_ms"}],"optional":false,"name":"dbserver3.public.x.Envelope"},"payload":{"before":null,"after":{"p":{"x":3.0,"y":4.0,"wkb":"AQEAAAAAAAAAAAAIQAAAAAAAABBA","srid":null}},"source":{"version":"0.9.5.Final","connector":"postgresql","name":"dbserver3","db":"test","ts_usec":1560855538548000,"txId":7877,"lsn":142534576,"schema":"public","table":"x","snapshot":true,"last_snapshot_record":true,"xmin":null},"op":"r","ts_ms":1560855538548}}

Manabu Kamimura

2019年6月18日火曜日 13時16分56秒 UTC+9 Jiri Pechanec:

[Manabu Kamimura]

Hi,

Sorry for taking your time. I may failed to install/configure the postgreSQL server with decoderbuf.

I heard that another person tried the same operation on the postgresql docker image provided by debezium.

(In my case, I installed the postgresql 9.2 and upgraded to 9.6.13 and tried to configure the server)

The postgresql image is used as the database server for the same web application and connected the debezium with decoderbuf.

The segmentation fault does not occur at this time.

Best Regards,

Manabu Kamimura

2019年6月18日火曜日 20時06分38秒 UTC+9 Manabu Kamimura:

[Jiri Pechanec]

Hi,

great that you've found it out. Thanks for letting us now!

J.