Uploaded image for project: 'Apache IoTDB'
  1. Apache IoTDB
  2. IOTDB-1651

Sync 模块 out of sequence

    XMLWordPrintableJSON

Details

    • 2021-10-Hou

    Description

      Sometimes sync process throws "Read time out" or some other exceptions because of unstable connection, and then thrift will throw a "out of sequence".
      2021-07-14 15:00:15,142 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:430 - Receiver has received schema successfully.
      2021-07-14 15:00:15,163 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:251 - There are 1 data dirs to be synced.
      2021-07-14 15:00:15,163 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:254 - Start to sync data in data dir /home/user/xbox/apache-iotdb-0.12.1/data/data, the process is 1/1
      2021-07-14 15:00:15,165 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.m.SyncFileManager:95 - Start to get current local files in data folder /home/user/xbox/apache-iotdb-0.12.1/data/data
      2021-07-14 15:00:15,174 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.m.SyncFileManager:175 - Start to get last local files from last local file info /home/user/xbox/apache-iotdb-0.12.1/data/data/sync-sender/140.179.49.92_20919/last_local_files.txt
      2021-07-14 15:00:15,181 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.r.SyncSenderLogAnalyzer:89 - log file /home/user/xbox/apache-iotdb-0.12.1/data/data/sync-sender/140.179.49.92_20919/sync.log doesn't exist.
      2021-07-14 15:00:15,279 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:492 - Sync process starts to transfer data of storage group root.Xinjiang, it has 1 virtual storage groups.
      2021-07-14 15:00:15,281 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:546 - There has no deleted files to be synced in storage group root.Xinjiang
      2021-07-14 15:00:15,283 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:575 - Sync process starts to transfer data of storage group root.Xinjiang
      2021-07-14 15:00:17,708 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:664 - Receiver has received /home/user/xbox/apache-iotdb-0.12.1/data/data/sync-sender/140.179.49.92_20919/snapshot/root.Xinjiang/0/0/1626217093303-253-2-0.tsfile.resource successfully.
      2021-07-14 15:00:39,394 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:208 - Sync process for receiver 140.179.49.92_20919 is in execution!
      2021-07-14 15:01:39,972 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:208 - Sync process for receiver 140.179.49.92_20919 is in execution!
      2021-07-14 15:02:32,115 [pool-1-IoTDB-sync-client-timer-1] ERROR o.a.i.d.s.s.t.SyncClient:533 - cannot finish sync process
      org.apache.iotdb.db.exception.SyncConnectionException: Cannot sync data with receiver.java.net.SocketTimeoutException: Read timed out
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncSingleFile(SyncClient.java:671)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncDataFilesInOneGroup(SyncClient.java:583)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.sync(SyncClient.java:512)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncAll(SyncClient.java:271)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.lambda$startTimedTask$2(SyncClient.java:222)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
      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)
      2021-07-14 15:02:32,131 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:273 - Finish to sync data in data dir /home/user/xbox/apache-iotdb-0.12.1/data/data, the process is 1/1
      2021-07-14 15:02:32,688 [pool-1-IoTDB-sync-client-timer-1] ERROR o.a.i.d.s.s.t.SyncClient:287 - Unable to connect to receiver.
      org.apache.thrift.TApplicationException: endSync failed: out of sequence response: expected 11 but got 10
      at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:86)
      at org.apache.iotdb.service.sync.thrift.SyncService$Client.recv_endSync(SyncService.java:248)
      at org.apache.iotdb.service.sync.thrift.SyncService$Client.endSync(SyncService.java:236)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncAll(SyncClient.java:283)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.lambda$startTimedTask$2(SyncClient.java:222)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
      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)
      2021-07-14 15:03:33,373 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:430 - Receiver has received schema successfully.
      2021-07-14 15:03:33,379 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:251 - There are 1 data dirs to be synced.
      2021-07-14 15:03:33,380 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:254 - Start to sync data in data dir /home/user/xbox/apache-iotdb-0.12.1/data/data, the process is 1/1
      2021-07-14 15:03:33,384 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.m.SyncFileManager:95 - Start to get current local files in data folder /home/user/xbox/apache-iotdb-0.12.1/data/data
      2021-07-14 15:03:33,409 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.m.SyncFileManager:175 - Start to get last local files from last local file info /home/user/xbox/apache-iotdb-0.12.1/data/data/sync-sender/140.179.49.92_20919/last_local_files.txt
      2021-07-14 15:03:33,415 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.r.SyncSenderLogAnalyzer:89 - log file /home/user/xbox/apache-iotdb-0.12.1/data/data/sync-sender/140.179.49.92_20919/sync.log doesn't exist.
      2021-07-14 15:03:33,484 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:492 - Sync process starts to transfer data of storage group root.Xinjiang, it has 1 virtual storage groups.
      2021-07-14 15:03:33,485 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:546 - There has no deleted files to be synced in storage group root.Xinjiang
      2021-07-14 15:03:33,485 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:575 - Sync process starts to transfer data of storage group root.Xinjiang
      2021-07-14 15:03:33,886 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:664 - Receiver has received /home/user/xbox/apache-iotdb-0.12.1/data/data/sync-sender/140.179.49.92_20919/snapshot/root.Xinjiang/0/0/1626217093303-253-2-0.tsfile.resource successfully.
      2021-07-14 15:03:43,195 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:208 - Sync process for receiver 140.179.49.92_20919 is in execution!
      2021-07-14 15:04:43,282 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:208 - Sync process for receiver 140.179.49.92_20919 is in execution!
      2021-07-14 15:05:32,914 [pool-1-IoTDB-sync-client-timer-2] ERROR o.a.i.d.s.s.t.SyncClient:533 - cannot finish sync process
      org.apache.iotdb.db.exception.SyncConnectionException: Cannot sync data with receiver.java.net.SocketTimeoutException: Read timed out
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncSingleFile(SyncClient.java:671)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncDataFilesInOneGroup(SyncClient.java:583)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.sync(SyncClient.java:512)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncAll(SyncClient.java:271)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.lambda$startTimedTask$2(SyncClient.java:222)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
      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)
      2021-07-14 15:05:32,926 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:273 - Finish to sync data in data dir /home/user/xbox/apache-iotdb-0.12.1/data/data, the process is 1/1
      2021-07-14 15:05:33,352 [pool-1-IoTDB-sync-client-timer-2] ERROR o.a.i.d.s.s.t.SyncClient:287 - Unable to connect to receiver.
      org.apache.thrift.TApplicationException: endSync failed: out of sequence response: expected 11 but got 10
      at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:86)
      at org.apache.iotdb.service.sync.thrift.SyncService$Client.recv_endSync(SyncService.java:248)
      at org.apache.iotdb.service.sync.thrift.SyncService$Client.endSync(SyncService.java:236)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncAll(SyncClient.java:283)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.lambda$startTimedTask$2(SyncClient.java:222)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
      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)
      2021-07-14 15:06:34,048 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:430 - Receiver has received schema successfully.
      2021-07-14 15:06:34,050 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:251 - There are 1 data dirs to be synced.
      2021-07-14 15:06:34,051 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:254 - Start to sync data in data dir /home/user/xbox/apache-iotdb-0.12.1/data/data, the process is 1/1
      2021-07-14 15:06:34,052 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.m.SyncFileManager:95 - Start to get current local files in data folder /home/user/xbox/apache-iotdb-0.12.1/data/data
      2021-07-14 15:06:34,061 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.m.SyncFileManager:175 - Start to get last local files from last local file info /home/user/xbox/apache-iotdb-0.12.1/data/data/sync-sender/140.179.49.92_20919/last_local_files.txt
      2021-07-14 15:06:34,063 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.r.SyncSenderLogAnalyzer:89 - log file /home/user/xbox/apache-iotdb-0.12.1/data/data/sync-sender/140.179.49.92_20919/sync.log doesn't exist.
      2021-07-14 15:06:34,134 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:492 - Sync process starts to transfer data of storage group root.Xinjiang, it has 1 virtual storage groups.
      2021-07-14 15:06:34,135 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:546 - There has no deleted files to be synced in storage group root.Xinjiang
      2021-07-14 15:06:34,135 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:575 - Sync process starts to transfer data of storage group root.Xinjiang
      2021-07-14 15:06:34,526 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:664 - Receiver has received /home/user/xbox/apache-iotdb-0.12.1/data/data/sync-sender/140.179.49.92_20919/snapshot/root.Xinjiang/0/0/1626217093303-253-2-0.tsfile.resource successfully.
      2021-07-14 15:06:43,286 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:208 - Sync process for receiver 140.179.49.92_20919 is in execution!
      2021-07-14 15:07:43,287 [pool-1-IoTDB-sync-client-timer-2] INFO o.a.i.d.s.s.t.SyncClient:208 - Sync process for receiver 140.179.49.92_20919 is in execution!
      2021-07-14 15:08:26,740 [pool-1-IoTDB-sync-client-timer-1] ERROR o.a.i.d.s.s.t.SyncClient:533 - cannot finish sync process
      org.apache.iotdb.db.exception.SyncConnectionException: Cannot sync data with receiver.java.net.SocketTimeoutException: Read timed out
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncSingleFile(SyncClient.java:671)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncDataFilesInOneGroup(SyncClient.java:583)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.sync(SyncClient.java:512)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncAll(SyncClient.java:271)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.lambda$startTimedTask$2(SyncClient.java:222)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
      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)
      2021-07-14 15:08:26,746 [pool-1-IoTDB-sync-client-timer-1] INFO o.a.i.d.s.s.t.SyncClient:273 - Finish to sync data in data dir /home/user/xbox/apache-iotdb-0.12.1/data/data, the process is 1/1
      2021-07-14 15:08:27,747 [pool-1-IoTDB-sync-client-timer-1] ERROR o.a.i.d.s.s.t.SyncClient:287 - Unable to connect to receiver.
      org.apache.thrift.transport.TTransportException: java.net.SocketTimeoutException: Read timed out
      at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:178)
      at org.apache.thrift.transport.TTransport.readAll(TTransport.java:109)
      at org.apache.iotdb.rpc.TElasticFramedTransport.readFrame(TElasticFramedTransport.java:112)
      at org.apache.iotdb.rpc.TElasticFramedTransport.read(TElasticFramedTransport.java:107)
      at org.apache.thrift.transport.TTransport.readAll(TTransport.java:109)
      at org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:463)
      at org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:361)
      at org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:244)
      at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:77)
      at org.apache.iotdb.service.sync.thrift.SyncService$Client.recv_endSync(SyncService.java:248)
      at org.apache.iotdb.service.sync.thrift.SyncService$Client.endSync(SyncService.java:236)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.syncAll(SyncClient.java:283)
      at org.apache.iotdb.db.sync.sender.transfer.SyncClient.lambda$startTimedTask$2(SyncClient.java:222)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
      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: java.net.SocketTimeoutException: Read timed out
      at java.net.SocketInputStream.socketRead0(Native Method)
      at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
      at java.net.SocketInputStream.read(SocketInputStream.java:171)
      at java.net.SocketInputStream.read(SocketInputStream.java:141)
      at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
      at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
      at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
      at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:176)
      ... 19 common frames omitted

      solution:
      when a TException is thrown, make a new client connect to the receiver.

      Attachments

        Issue Links

          is related to

          Bug - A problem which impairs or prevents the functions of the product. IOTDB-1939 sync : The receiver receives more data than the sender sends

          • Major - Major loss of function.
          • In Progress
          links to

          Web Link GitHub Pull Request #4087

          Web Link GitHub Pull Request #4246

          Activity

            People

              yschengzi yusicheng
              hail Hai Liu
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Time Tracking

                  Estimated:
                  Original Estimate - 16h
                  16h
                  Remaining:
                  Remaining Estimate - 16h
                  16h
                  Logged:
                  Time Spent - Not Specified
                  Not Specified