Fwd: postgresql Logical Replication Stream fails wit h “Database connection failed when reading from copy”

Dave,
I am using Windows 10 and I do not have tcp_keep* settings set in my
regedit
location :
HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Tcpip\Parameters

So all these settings should be windows default values.

Regards
Shailesh
On Wed, 5 Sep 2018, 00:14 Dave Cramer, <[email protected]> wrote:

> What O/S are you using ? Can you see what the kernel tcp_keep* settings
> are ?
>
> On Tue, 4 Sep 2018 at 13:15, Jammie <[email protected]> wrote:
>
>> PGProperty.TCP_KEEP_ALIVE.set(connectionProperties, "true");
>>
>> this is how I am setting.
>>
>> On Tue, Sep 4, 2018 at 10:44 PM Dave Cramer <[email protected]>
>> wrote:
>>
>>> Are you specifying *tcpKeepAlive=true *in the connection string ?
>>>
>>> On Tue, 4 Sep 2018 at 12:27, Jammie <[email protected]> wrote:
>>>
>>>> The issue is still coming for me.
>>>>
>>>> One more thing to note here is my postgres database and Java program
>>>> that stream data is on the same box.
>>>>
>>>> Regards
>>>> Shailesh
>>>>
>>>> On Tue, Sep 4, 2018 at 9:26 PM Jammie <[email protected]>
>>>> wrote:
>>>>
>>>>> Ok, I'll check it out.
>>>>>
>>>>> On Tue, 4 Sep 2018, 20:59 Dave Cramer, <[email protected]> wrote:
>>>>>
>>>>>> Have a look at https://issues.jboss.org/browse/DBZ-218
>>>>>>
>>>>>> I think just setting "tcpKeepAlive=true" should work. Can you try
>>>>>> that and get back to me?
>>>>>>
>>>>>> On Tue, 4 Sep 2018 at 10:53, Jammie <[email protected]>
>>>>>> wrote:
>>>>>>
>>>>>>> One query is ,
>>>>>>> In my program I do not set
>>>>>>>
>>>>>>> stream.setAppliedPosition() or stream.setFlushLSN().
>>>>>>>
>>>>>>> So does that mean we will not be able to send the updates to server.
>>>>>>> and It is necessary to send this message periodically ?
>>>>>>>
>>>>>>> Regards
>>>>>>> Shailesh
>>>>>>>
>>>>>>> On Tue, Sep 4, 2018 at 8:05 PM Jammie <[email protected]>
>>>>>>> wrote:
>>>>>>>
>>>>>>>> Ok. Thank you very much. !! Appreciate your time here .
>>>>>>>>
>>>>>>>> On Tue, Sep 4, 2018 at 8:03 PM Dave Cramer <[email protected]>
>>>>>>>> wrote:
>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On Tue, 4 Sep 2018 at 10:32, Jammie <[email protected]>
>>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>>> Most of the time I have set
>>>>>>>>>>
>>>>>>>>>> .withStatusInterval(20, TimeUnit.SECONDS)
>>>>>>>>>>
>>>>>>>>>> Just that to see If 0 can solve this issue I tried it once.
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>> No, that is worse.
>>>>>>>>>
>>>>>>>>> I'll build a jar for you to try.
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On Tue, Sep 4, 2018 at 7:59 PM Jammie <[email protected]>
>>>>>>>>>> wrote:
>>>>>>>>>>
>>>>>>>>>>> Sorry I have not done building of driver myself. Please help If
>>>>>>>>>>> you can do that for me or If you can share steps I can do that.
>>>>>>>>>>>
>>>>>>>>>>> Also would like to understand If we got the root cause fixed :
>>>>>>>>>>>
>>>>>>>>>>> Here is my further observation for this issue :
>>>>>>>>>>> 1) The issue comes at different point in time while stream is
>>>>>>>>>>> doing its job e.g. writing copy/reading copy/ending copy. I think
>>>>>>>>>>> underlying issue is Socket issue only.
>>>>>>>>>>> 2) Once this issue comes the stream object cant even be closed.
>>>>>>>>>>> even stream.close() throws the same error e.g. 'error reading copy`. Even
>>>>>>>>>>> SQL Connection object is unusable e.g. querying to database using that
>>>>>>>>>>> object hangs. However I see both stream.isClose() and connection.isClose()
>>>>>>>>>>> is false.
>>>>>>>>>>>
>>>>>>>>>>> Regards
>>>>>>>>>>> Shailesh
>>>>>>>>>>>
>>>>>>>>>>> On Tue, Sep 4, 2018 at 7:52 PM Dave Cramer <
>>>>>>>>>>> [email protected]> wrote:
>>>>>>>>>>>
>>>>>>>>>>>> Hey,
>>>>>>>>>>>>
>>>>>>>>>>>> So here's what I think is happening. The keep alive timeout
>>>>>>>>>>>> exactly the same as the option in the slot.
>>>>>>>>>>>>
>>>>>>>>>>>> So in
>>>>>>>>>>>>
>>>>>>>>>>>> private boolean isTimeUpdate() {
>>>>>>>>>>>>   /* a value of 0 disables automatic updates */
>>>>>>>>>>>>   if ( updateInterval == 0 ) {
>>>>>>>>>>>>     return false;
>>>>>>>>>>>>   }
>>>>>>>>>>>>   long diff = System.currentTimeMillis() - lastStatusUpdate;
>>>>>>>>>>>>   return diff >= updateInterval;
>>>>>>>>>>>> }
>>>>>>>>>>>>
>>>>>>>>>>>> change this to be
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> return diff >= updateInterval-100;
>>>>>>>>>>>>
>>>>>>>>>>>> or something similar to get it to update before it times out on
>>>>>>>>>>>> the server
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> Can you build the driver ? If not I'll send you a driver with
>>>>>>>>>>>> some mods to change
>>>>>>>>>>>>
>>>>>>>>>>>> On Tue, 4 Sep 2018 at 08:40, Dave Cramer <
>>>>>>>>>>>> [email protected]> wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> On Mon, 3 Sep 2018 at 21:03, Jammie <
>>>>>>>>>>>>> [email protected]> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>>> Hi Dave,
>>>>>>>>>>>>>> thanks for the response !!
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> 1) I have tried latest driver 42.2.5 as well the same
>>>>>>>>>>>>>> exception can be reproduced easily.
>>>>>>>>>>>>>> 2) I have tried postgres V10 version along with 9.6.4 same
>>>>>>>>>>>>>> issue could be reproduced.
>>>>>>>>>>>>>> The server side log says :
>>>>>>>>>>>>>> *2018-09-02 23:40:52 EDT LOG:  could not receive data from
>>>>>>>>>>>>>> client: An existing connection was forcibly closed by the remote host.*
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> In one of the instance I had enabled JDBC trace and this is
>>>>>>>>>>>>>> what the last few lines are :
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> *Sep 03, 2018 3:37:52 AM org.postgresql.core.v3.*
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> *QueryExecutorImpl receiveRFQFINEST:  <=BE
>>>>>>>>>>>>>> ReadyForQuery(I)Sep 03, 2018 3:37:52 AM org.postgresql.jdbc.*
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> *PgResultSet getIntFINEST:   getInt columnIndex: 1Sep 03,
>>>>>>>>>>>>>> 2018 3:37:52 AM org.postgresql.jdbc.*
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> *PgConnection setAutoCommitFINE:   setAutoCommit = falseSep
>>>>>>>>>>>>>> 03, 2018 3:37:53 AM org.postgresql.core.**QueryExecutorBase
>>>>>>>>>>>>>> close*
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I also see Socket reset error some times :
>>>>>>>>>>>>>> ---------------------
>>>>>>>>>>>>>> *Sep 03, 2018 3:29:42 AM org.postgresql.core.v3.*
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> *QueryExecutorImpl processCopyResultsFINEST:  <=BE
>>>>>>>>>>>>>> CopyDataSep 03, 2018 3:29:42 AM org.postgresql.core.v3.*
>>>>>>>>>>>>>> *replication.*
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> *V3PGReplicationStream processKeepAliveMessageFINEST:   <=BE
>>>>>>>>>>>>>> Keepalive(lastServerWal: 0/2DD0218, clock: 9/3/18 3:29 AM needReply:
>>>>>>>>>>>>>> false)Sep 03, 2018 3:30:40 AM org.postgresql.core.*
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> *QueryExecutorBase closeFINEST:  FE=> TerminateSep 03, 2018
>>>>>>>>>>>>>> 3:30:40 AM org.postgresql.core.*
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> *QueryExecutorBase closeFINEST: Discarding IOException on
>>>>>>>>>>>>>> close:java.net.SocketException: Connection reset by peer: socket write
>>>>>>>>>>>>>> error    at java.net.SocketOutputStream.*
>>>>>>>>>>>>>> *socketWrite0(Native Method)    at
>>>>>>>>>>>>>> java.net.SocketOutputStream.**socketWrite(*
>>>>>>>>>>>>>> *SocketOutputStream.java:122)    at
>>>>>>>>>>>>>> java.net.SocketOutputStream.**write(SocketOutputStream.java:*
>>>>>>>>>>>>>> *166)    at java.io.BufferedOutputStream.**flushBuffer(*
>>>>>>>>>>>>>> *BufferedOutputStream.java:93)    at
>>>>>>>>>>>>>> java.io.BufferedOutputStream.**flush(BufferedOutputStream.*
>>>>>>>>>>>>>> *java:151)    at org.postgresql.core.PGStream.*
>>>>>>>>>>>>>> *flush(PGStream.java:514)    at org.postgresql.core.*
>>>>>>>>>>>>>> *QueryExecutorBase.close(*
>>>>>>>>>>>>>> *QueryExecutorBase.java:136)    at org.postgresql.jdbc.*
>>>>>>>>>>>>>> *PgConnection.close(*
>>>>>>>>>>>>>> *PgConnection.java:659)    at com.datamirror.ts.scrapers.*
>>>>>>>>>>>>>> *postgresqlscraper.**PostgreSQLLogicalLogReaderImpl*
>>>>>>>>>>>>>> *.readLog(**PostgreSQLLogicalLogReaderImpl*
>>>>>>>>>>>>>> *.java:208)    at com.datamirror.ts.scrapers.*
>>>>>>>>>>>>>> *postgresqlscraper.**PostgreSQLLogReader.readLog(*
>>>>>>>>>>>>>> *PostgreSQLLogReader.java:174)    at
>>>>>>>>>>>>>> com.datamirror.ts.scrapers.**cdc.LogReader.execute(*
>>>>>>>>>>>>>> *LogReader.java:341)    at com.datamirror.ts.scrapers.*
>>>>>>>>>>>>>> *cdc.LogReader$**LogReaderPipelineJob.execute(*
>>>>>>>>>>>>>> *LogReader.java:114)    at com.datamirror.ts.engine.*
>>>>>>>>>>>>>> *component.PipelineThread.**runThread(PipelineThread.java:*
>>>>>>>>>>>>>> *217)    at com.datamirror.ts.util.*
>>>>>>>>>>>>>> *TsThread.run(TsThread.java:*
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> *130)Sep 03, 2018 3:30:40 AM org.postgresql.Driver
>>>>>>>>>>>>>> connectFINEST:  FE=> Terminate*
>>>>>>>>>>>>>> -------------------------
>>>>>>>>>>>>>> 3) Other than this I have tried to set PGProperty
>>>>>>>>>>>>>> TCP_KEEP_ALIVE to true and SOCKET_TIMEOUT as 0.
>>>>>>>>>>>>>> Also SetStatusInterval of the stream also to 0 but these did
>>>>>>>>>>>>>> not help the purpose.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> The issue is very consistent and can be reproduced easily.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Regards
>>>>>>>>>>>>>> Shailesh
>>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> Pretty sure I know how to fix this,
>>>>>>>>>>>>>
>>>>>>>>>>>>> Give me a few hours..
>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> On Tue, Sep 4, 2018 at 12:51 AM Dave Cramer <[email protected]>
>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Hi,
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Off the top of my head I don't have any advice. Can you try
>>>>>>>>>>>>>>> the latest driver though and see if it still exists.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Are there any messages on the server saying that it closed
>>>>>>>>>>>>>>> the connection ?
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Dave Cramer
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> [email protected]
>>>>>>>>>>>>>>> www.postgresintl.com
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> On Mon, 3 Sep 2018 at 06:34, Jammie <
>>>>>>>>>>>>>>> [email protected]> wrote:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Hi I am reading from logical replication stream
>>>>>>>>>>>>>>>> continuously in infinite while loop. and I have another program that is
>>>>>>>>>>>>>>>> continuously populating a table in the same database. I notice that after
>>>>>>>>>>>>>>>> some time (around 5-10 minutes). I always get the exception
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> org.postgresql.util.PSQLException: Database connection failed when reading from copy
>>>>>>>>>>>>>>>> at org.postgresql.core.v3.QueryExecutorImpl.readFromCopy(QueryExecutorImpl.java:1035)
>>>>>>>>>>>>>>>> at org.postgresql.core.v3.CopyDualImpl.readFromCopy(CopyDualImpl.java:41)
>>>>>>>>>>>>>>>> at org.postgresql.core.v3.replication.V3PGReplicationStream.receiveNextData(V3PGReplicationStream.java:155)
>>>>>>>>>>>>>>>> at org.postgresql.core.v3.replication.V3PGReplicationStream.readInternal(V3PGReplicationStream.java:124)
>>>>>>>>>>>>>>>> at org.postgresql.core.v3.replication.V3PGReplicationStream.read(V3PGReplicationStream.java:70)
>>>>>>>>>>>>>>>> at com.datamirror.ts.scrapers.postgresqlscraper.PGStreamReceiver.main(PGStreamReceiver.java:60)
>>>>>>>>>>>>>>>> Caused by: java.net.SocketException: Connection reset
>>>>>>>>>>>>>>>> at java.net.SocketInputStream.read(SocketInputStream.java:220)
>>>>>>>>>>>>>>>> at java.net.SocketInputStream.read(SocketInputStream.java:152)
>>>>>>>>>>>>>>>> at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>