Uploaded image for project: 'Debezium'
  1. Debezium
  2. DBZ-4966

Intermittent failure of RedisStreamIT.testRedisConnectionRetry

XMLWordPrintable

    • False
    • None
    • False

      The log snippet is

      2022-04-07 09:58:18,121 INFO  [io.deb.uti.Threads] (debezium-postgresconnector-testc-change-event-source-coordinator) Creating thread debezium-postgresconnector-testc-keep-alive
      2022-04-07 09:58:18,146 INFO  [io.deb.con.pos.PostgresSchema] (debezium-postgresconnector-testc-change-event-source-coordinator) REPLICA IDENTITY for 'inventory.customers' is 'FULL'; UPDATE AND DELETE events will contain the previous values of all the columns
      2022-04-07 09:58:18,147 INFO  [io.deb.con.pos.PostgresSchema] (debezium-postgresconnector-testc-change-event-source-coordinator) REPLICA IDENTITY for 'inventory.redis_test2' is 'DEFAULT'; UPDATE and DELETE events will contain previous values only for PK columns
      2022-04-07 09:58:18,150 INFO  [io.deb.con.pos.PostgresStreamingChangeEventSource] (debezium-postgresconnector-testc-change-event-source-coordinator) Searching for WAL resume position
      Entries in testc.inventory.redis_test2:22
      2022-04-07 09:58:18,390 WARN  [io.deb.ser.red.RedisStreamChangeConsumer] (pool-7-thread-1) Redis runs OOM, 28 command(s) failed
      2022-04-07 09:58:18,992 WARN  [io.deb.ser.red.RedisStreamChangeConsumer] (pool-7-thread-1) Redis runs OOM, 28 command(s) failed
      Pausing container
      Creating new redis_test table and inserting 5 records to it
      2022-04-07 09:58:20,374 INFO  [io.deb.jdb.JdbcConnection] (pool-3-thread-1) Connection gracefully closed
      Sleeping for 5 seconds to simulate no connection errors
      2022-04-07 09:58:20,695 INFO  [io.deb.con.pos.con.WalPositionLocator] (debezium-postgresconnector-testc-change-event-source-coordinator) First LSN 'LSN{0/2295E60}' received
      2022-04-07 09:58:20,696 INFO  [io.deb.con.pos.PostgresStreamingChangeEventSource] (debezium-postgresconnector-testc-change-event-source-coordinator) WAL resume position 'LSN{0/2295E60}' discovered
      2022-04-07 09:58:20,699 INFO  [io.deb.jdb.JdbcConnection] (pool-9-thread-1) Connection gracefully closed
      2022-04-07 09:58:20,724 INFO  [io.deb.uti.Threads] (debezium-postgresconnector-testc-change-event-source-coordinator) Requested thread factory for connector PostgresConnector, id = testc named = keep-alive
      2022-04-07 09:58:20,725 INFO  [io.deb.uti.Threads] (debezium-postgresconnector-testc-change-event-source-coordinator) Creating thread debezium-postgresconnector-testc-keep-alive
      2022-04-07 09:58:20,735 INFO  [io.deb.con.pos.PostgresStreamingChangeEventSource] (debezium-postgresconnector-testc-change-event-source-coordinator) Processing messages
      2022-04-07 09:58:20,736 INFO  [io.deb.con.pos.con.WalPositionLocator] (debezium-postgresconnector-testc-change-event-source-coordinator) Message with LSN 'LSN{0/2295E60}' arrived, switching off the filtering
      2022-04-07 09:58:23,209 ERROR [io.deb.ser.red.RedisStreamChangeConsumer] (pool-7-thread-1) Connection error: redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketTimeoutException: Read timed out
      	at redis.clients.jedis.util.RedisInputStream.ensureFill(RedisInputStream.java:204)
      	at redis.clients.jedis.util.RedisInputStream.readByte(RedisInputStream.java:42)
      	at redis.clients.jedis.Protocol.process(Protocol.java:126)
      	at redis.clients.jedis.Protocol.read(Protocol.java:192)
      	at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:316)
      	at redis.clients.jedis.Connection.getMany(Connection.java:328)
      	at redis.clients.jedis.Pipeline.syncAndReturnAll(Pipeline.java:81)
      	at io.debezium.server.redis.RedisStreamChangeConsumer.lambda$handleBatch$1(RedisStreamChangeConsumer.java:164)
      	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
      	at java.base/java.util.stream.IntPipeline$1$1.accept(IntPipeline.java:180)
      	at java.base/java.util.stream.Streams$RangeIntSpliterator.forEachRemaining(Streams.java:104)
      	at java.base/java.util.Spliterator$OfInt.forEachRemaining(Spliterator.java:711)
      	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
      	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
      	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
      	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
      	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
      	at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
      	at io.debezium.server.redis.RedisStreamChangeConsumer.handleBatch(RedisStreamChangeConsumer.java:127)
      	at io.debezium.embedded.ConvertingEngineBuilder.lambda$notifying$2(ConvertingEngineBuilder.java:83)
      	at io.debezium.embedded.EmbeddedEngine.run(EmbeddedEngine.java:821)
      	at io.debezium.embedded.ConvertingEngineBuilder$2.run(ConvertingEngineBuilder.java:192)
      	at io.debezium.server.DebeziumServer.lambda$start$1(DebeziumServer.java:150)
      	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
      	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
      	at java.base/java.lang.Thread.run(Thread.java:833)
      Caused by: java.net.SocketTimeoutException: Read timed out
      	at java.base/sun.nio.ch.NioSocketImpl.timedRead(NioSocketImpl.java:283)
      	at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:309)
      	at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350)
      	at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803)
      	at java.base/java.net.Socket$SocketInputStream.read(Socket.java:966)
      	at java.base/java.io.InputStream.read(InputStream.java:218)
      	at redis.clients.jedis.util.RedisInputStream.ensureFill(RedisInputStream.java:198)
      	... 25 more
      
      Unpausing container
      2022-04-07 09:58:25,396 INFO  [io.deb.ser.red.RedisConnection] (pool-7-thread-1) Using Jedis 'Jedis{Connection{DefaultJedisSocketFactory{localhost:49188}}}'
      Error:  Tests run: 3, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 77.481 s <<< FAILURE! - in io.debezium.server.redis.RedisStreamIT
      Error:  io.debezium.server.redis.RedisStreamIT.testRedisConnectionRetry  Time elapsed: 65.15 s  <<< ERROR!
      org.awaitility.core.ConditionTimeoutException: Condition with io.debezium.server.redis.RedisStreamIT was not fulfilled within 1 minutes.
      	at io.debezium.server.redis.RedisStreamIT.getStreamLength(RedisStreamIT.java:51)
      	at io.debezium.server.redis.RedisStreamIT.testRedisConnectionRetry(RedisStreamIT.java:104)
      
      [INFO] Running io.debezium.server.redis.RedisOffsetIT
      

      The PR https://github.com/debezium/debezium/pull/3367 tried but failed to reproduce the issue.

              Unassigned Unassigned
              jpechane Jiri Pechanec
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

                Created:
                Updated:
                Resolved: