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

RedisSchemaHistoryIT fails randomly

XMLWordPrintable

      Failed e.g. here with

      2024-03-20T22:39:47.2350205Z 2024-03-20 22:39:47,204 ERROR [io.deb.ser.red.RedisStreamChangeConsumer] (pool-7-thread-1) Connection error: io.debezium.storage.redis.RedisClientConnectionException: redis.clients.jedis.exceptions.JedisConnectionException: 
      java.net.SocketTimeoutException: Read timed out
      2024-03-20T22:39:47.2353642Z    at io.debezium.storage.redis.JedisClient.tryErrors(JedisClient.java:119)
      2024-03-20T22:39:47.2354811Z    at io.debezium.storage.redis.JedisClient.info(JedisClient.java:125)
      2024-03-20T22:39:47.2355923Z    at io.debezium.server.redis.RedisMemoryThreshold.memoryTuple(RedisMemoryThreshold.java:105)
      2024-03-20T22:39:47.2356877Z    at io.debezium.server.redis.RedisMemoryThreshold.checkMemory(RedisMemoryThreshold.java:58)
      2024-03-20T22:39:47.2357928Z    at io.debezium.server.redis.RedisStreamChangeConsumer.lambda$handleBatch$3(RedisStreamChangeConsumer.java:184)
      2024-03-20T22:39:47.2359134Z    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
      2024-03-20T22:39:47.2359924Z    at java.base/java.util.stream.IntPipeline$1$1.accept(IntPipeline.java:180)
      2024-03-20T22:39:47.2360742Z    at java.base/java.util.stream.Streams$RangeIntSpliterator.forEachRemaining(Streams.java:104)
      2024-03-20T22:39:47.2361574Z    at java.base/java.util.Spliterator$OfInt.forEachRemaining(Spliterator.java:711)
      2024-03-20T22:39:47.2362364Z    at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
      2024-03-20T22:39:47.2363222Z    at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
      2024-03-20T22:39:47.2364110Z    at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
      2024-03-20T22:39:47.2364934Z    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
      2024-03-20T22:39:47.2365732Z    at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
      2024-03-20T22:39:47.2366486Z    at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
      2024-03-20T22:39:47.2367578Z    at io.debezium.server.redis.RedisStreamChangeConsumer.handleBatch(RedisStreamChangeConsumer.java:147)
      2024-03-20T22:39:47.2368716Z    at io.debezium.embedded.async.ParallelSmtAndConvertBatchProcessor.processRecords(ParallelSmtAndConvertBatchProcessor.java:56)
      2024-03-20T22:39:47.2369827Z    at io.debezium.embedded.async.AsyncEmbeddedEngine$PollRecords.doCall(AsyncEmbeddedEngine.java:1155)
      2024-03-20T22:39:47.2370734Z    at io.debezium.embedded.async.AsyncEmbeddedEngine$PollRecords.doCall(AsyncEmbeddedEngine.java:1136)
      2024-03-20T22:39:47.2371547Z    at io.debezium.embedded.async.RetryingCallable.call(RetryingCallable.java:47)
      2024-03-20T22:39:47.2372224Z    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
      2024-03-20T22:39:47.2372911Z    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
      2024-03-20T22:39:47.2373598Z    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
      2024-03-20T22:39:47.2374346Z    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
      2024-03-20T22:39:47.2375191Z    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
      2024-03-20T22:39:47.2375832Z    at java.base/java.lang.Thread.run(Thread.java:840)
      2024-03-20T22:39:47.2376586Z Caused by: redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketTimeoutException: Read timed out
      2024-03-20T22:39:47.2377508Z    at redis.clients.jedis.util.RedisInputStream.ensureFill(RedisInputStream.java:204)
      2024-03-20T22:39:47.2378268Z    at redis.clients.jedis.util.RedisInputStream.readByte(RedisInputStream.java:42)
      2024-03-20T22:39:47.2378913Z    at redis.clients.jedis.Protocol.process(Protocol.java:126)
      2024-03-20T22:39:47.2379427Z    at redis.clients.jedis.Protocol.read(Protocol.java:192)
      2024-03-20T22:39:47.2380095Z    at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:316)
      2024-03-20T22:39:47.2380858Z    at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:262)
      2024-03-20T22:39:47.2381647Z    at redis.clients.jedis.Connection.getBulkReply(Connection.java:252)
      2024-03-20T22:39:47.2382183Z    at redis.clients.jedis.Jedis.info(Jedis.java:3314)
      2024-03-20T22:39:47.2382759Z    at io.debezium.storage.redis.JedisClient.lambda$info$13(JedisClient.java:125)
      2024-03-20T22:39:47.2383454Z    at io.debezium.storage.redis.JedisClient.tryErrors(JedisClient.java:116)
      2024-03-20T22:39:47.2383941Z    ... 25 more
      2024-03-20T22:39:47.2384283Z Caused by: java.net.SocketTimeoutException: Read timed out
      2024-03-20T22:39:47.2384864Z    at java.base/sun.nio.ch.NioSocketImpl.timedRead(NioSocketImpl.java:288)
      2024-03-20T22:39:47.2385501Z    at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:314)
      2024-03-20T22:39:47.2386108Z    at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:355)
      2024-03-20T22:39:47.2386708Z    at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:808)
      2024-03-20T22:39:47.2387307Z    at java.base/java.net.Socket$SocketInputStream.read(Socket.java:966)
      2024-03-20T22:39:47.2387879Z    at java.base/java.io.InputStream.read(InputStream.java:218)
      2024-03-20T22:39:47.2388522Z    at redis.clients.jedis.util.RedisInputStream.ensureFill(RedisInputStream.java:198)
      2024-03-20T22:39:47.2389062Z    ... 34 more
      

      Redis server seems to start successfully:

      2024-03-20T22:39:23.7920805Z 2024-03-20 22:39:23,748 INFO  [io.deb.ser.red.RedisTestResourceLifecycleManager] (docker-java-stream--208563368) STDOUT: 1:C 20 Mar 2024 22:39:23.550 # WARNING Memory overcommit must be enabled! Without it, a background save
       or replication may fail under low memory condition. Being disabled, it can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and 
      then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
      2024-03-20T22:39:23.7926638Z 2024-03-20 22:39:23,749 INFO  [io.deb.ser.red.RedisTestResourceLifecycleManager] (docker-java-stream--208563368) STDOUT: 1:C 20 Mar 2024 22:39:23.550 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
      2024-03-20T22:39:23.7930049Z 2024-03-20 22:39:23,749 INFO  [io.deb.ser.red.RedisTestResourceLifecycleManager] (docker-java-stream--208563368) STDOUT: 1:C 20 Mar 2024 22:39:23.550 * Redis version=7.2.4, bits=64, commit=00000000, modified=0, pid=1, just s
      tarted
      2024-03-20T22:39:23.7934172Z 2024-03-20 22:39:23,749 INFO  [io.deb.ser.red.RedisTestResourceLifecycleManager] (docker-java-stream--208563368) STDOUT: 1:C 20 Mar 2024 22:39:23.550 # Warning: no config file specified, using the default config. In order to
       specify a config file use redis-server /path/to/redis.conf
      2024-03-20T22:39:23.7938015Z 2024-03-20 22:39:23,749 INFO  [io.deb.ser.red.RedisTestResourceLifecycleManager] (docker-java-stream--208563368) STDOUT: 1:M 20 Mar 2024 22:39:23.550 * monotonic clock: POSIX clock_gettime
      2024-03-20T22:39:23.7941106Z 2024-03-20 22:39:23,749 INFO  [io.deb.ser.red.RedisTestResourceLifecycleManager] (docker-java-stream--208563368) STDOUT: 1:M 20 Mar 2024 22:39:23.551 * Running mode=standalone, port=6379.
      2024-03-20T22:39:23.7944039Z 2024-03-20 22:39:23,750 INFO  [io.deb.ser.red.RedisTestResourceLifecycleManager] (docker-java-stream--208563368) STDOUT: 1:M 20 Mar 2024 22:39:23.551 * Server initialized
      2024-03-20T22:39:23.7947236Z 2024-03-20 22:39:23,750 INFO  [io.deb.ser.red.RedisTestResourceLifecycleManager] (docker-java-stream--208563368) STDOUT: 1:M 20 Mar 2024 22:39:23.551 * Ready to accept connections tcp
      

      Sink seems to use correct address:

      2024-03-20T22:39:43.2291776Z 2024-03-20 22:39:43,207 INFO  [io.deb.sto.red.RedisCommonConfig] (main) Configuration for 'RedisStreamChangeConsumerConfig' with prefix 'debezium.sink.': {type=redis, redis.address=localhost:16379}
      2024-03-20T22:39:43.3288452Z 2024-03-20 22:39:43,244 INFO  [io.deb.sto.red.RedisConnection] (main) Using Redis client 'JedisClient [jedis=Jedis{Connection{DefaultJedisSocketFactory{localhost:16379}}}]'
      

      Schema history as well:

      2024-03-20T22:39:43.7303774Z 2024-03-20 22:39:43,637 WARN  [io.deb.ser.red.RedisOffsetBackingStore] (main) Class 'io.debezium.server.redis.RedisSchemaHistory' is deprecated and scheduled for removal, please use 'io.debezium.storage.redis.history.RedisSchemaHistory'
      2024-03-20T22:39:43.7307374Z 2024-03-20 22:39:43,648 INFO  [io.deb.sto.red.RedisCommonConfig] (main) Configuration for 'RedisSchemaHistoryConfig' with prefix 'schema.history.internal.': {redis.address=localhost:16379}
      2024-03-20T22:39:43.7309740Z 2024-03-20 22:39:43,658 INFO  [io.deb.sto.red.his.RedisSchemaHistory] (main) Starting RedisSchemaHistory
      2024-03-20T22:39:43.7312010Z 2024-03-20 22:39:43,686 INFO  [io.deb.sto.red.RedisConnection] (main) Using Redis client 'JedisClient [jedis=Jedis{Connection{DefaultJedisSocketFactory{localhost:16379}}}]'
      
      ...
      
      2024-03-20T22:39:44.1308034Z 2024-03-20 22:39:44,075 INFO  [io.deb.sto.red.his.RedisSchemaHistory] (pool-7-thread-1) Starting RedisSchemaHistory
      2024-03-20T22:39:44.1311001Z 2024-03-20 22:39:44,078 INFO  [io.deb.sto.red.RedisConnection] (pool-7-thread-1) Using Redis client 'JedisClient [jedis=Jedis{Connection{DefaultJedisSocketFactory{localhost:16379}}}]'
      

      and short after that fails with exception above.

            vjuranek@redhat.com Vojtech Juranek
            vjuranek@redhat.com Vojtech Juranek
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: