Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-53221

RollbackAll to zero with need an older snapshot error seen in the indexer logs

    XMLWordPrintable

Details

    • Untriaged
    • 1
    • Unknown

    Description

      Build Version: 6.6.5 build 153183 (toy-build)

      For steps to reproduce, please refer to https://issues.couchbase.com/browse/MB-53183

       

      Errors seen in the indexer nodes

      172.23.100.19 : index
      /opt/couchbase/var/lib/couchbase/logs/indexer.log:2022-08-02T00:24:05.987-07:00 [Info] StorageMgr::handleRollback 14333507792291946577 Discarding Snapshot SnapshotInfo: count:2201790 committed:false. Need older than last used snapshot bucket: test3, vbuckets: 1024 Crc64: 9439884715338000469 snapType FORCE_COMMIT -
      /opt/couchbase/var/lib/couchbase/logs/indexer.log:2022-08-02T00:24:05.992-07:00 [Info] StorageMgr::handleRollback 14333507792291946577 Discarding Snapshot SnapshotInfo: count:2201790 committed:false. Need older than last used snapshot bucket: test3, vbuckets: 1024 Crc64: 9439884715338000469 snapType FORCE_COMMIT -
      /opt/couchbase/var/lib/couchbase/logs/indexer.log:2022-08-02T00:24:10.919-07:00 [Info] StorageMgr::handleRollback 15613990554166204098 Discarding Snapshot SnapshotInfo: count:2253374 committed:false. Need older than last used snapshot bucket: test1, vbuckets: 1024 Crc64: 12977886264824415106 snapType FORCE_COMMIT -
      /opt/couchbase/var/lib/couchbase/logs/indexer.log:2022-08-02T00:24:10.921-07:00 [Info] StorageMgr::handleRollback 15613990554166204098 Discarding Snapshot SnapshotInfo: count:2253374 committed:false. Need older than last used snapshot bucket: test1, vbuckets: 1024 Crc64: 12977886264824415106 snapType FORCE_COMMIT 
      

      172.23.100.22 : index /opt/couchbase/var/lib/couchbase/logs/indexer.log:2022-08-02T00:24:07.198-07:00 [Info] StorageMgr::handleRollback 6033962826752699856 Discarding Snapshot SnapshotInfo: count:2201790 committed:false. Need older than last used snapshot bucket: test3, vbuckets: 1024 Crc64: 9439884715338000469 snapType FORCE_COMMIT - /opt/couchbase/var/lib/couchbase/logs/indexer.log:2022-08-02T00:24:07.200-07:00 [Info] StorageMgr::handleRollback 6033962826752699856 Discarding Snapshot SnapshotInfo: count:2201790 committed:false. Need older than last used snapshot bucket: test3, vbuckets: 1024 Crc64: 9439884715338000469 snapType FORCE_COMMIT - /opt/couchbase/var/lib/couchbase/logs/indexer.log:2022-08-02T00:24:19.360-07:00 [Info] StorageMgr::handleRollback 4303390511797119913 Discarding Snapshot SnapshotInfo: count:2253374 committed:false. Need older than last used snapshot bucket: test1, vbuckets: 1024 Crc64: 12977886264824415106 snapType FORCE_COMMIT - /opt/couchbase/var/lib/couchbase/logs/indexer.log:2022-08-02T00:24:19.362-07:00 [Info] StorageMgr::handleRollback 4303390511797119913 Discarding Snapshot SnapshotInfo: count:2253374 committed:false. Need older than last used snapshot bucket: test1, vbuckets: 1024 Crc64: 12977886264824415106 snapType FORCE_COMMIT - /opt/couchbase/var/lib/couchbase/logs/indexer.log:2022-08-02T00:50:13.033-07:00 [Info] StorageMgr::handleRollback 13886513233833622569 Discarding Snapshot SnapshotInfo: count:12451077 committed:false. Need older than last used snapshot bucket: test4, vbuckets: 1024 Crc64: 7157873520698326761 snapType FORCE_COMMIT - /opt/couchbase/var/lib/couchbase/logs/indexer.log:2022-08-02T00:50:13.035-07:00 [Info] StorageMgr::handleRollback 13886513233833622569 Discarding Snapshot
      

       

      [logs1] Log bundles

      cbcollect logs:
       
               url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1659428162/collectinfo-2022-08-02T081603-ns_1%40172.23.100.15.zip
               url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1659428162/collectinfo-2022-08-02T081603-ns_1%40172.23.100.16.zip
               url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1659428162/collectinfo-2022-08-02T081603-ns_1%40172.23.100.17.zip
               url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1659428162/collectinfo-2022-08-02T081603-ns_1%40172.23.100.19.zip
               url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1659428162/collectinfo-2022-08-02T081603-ns_1%40172.23.100.22.zip
               url : https://cb-jira.s3.us-east-2.amazonaws.com/logs/systestmon-1659428162/collectinfo-2022-08-02T081603-ns_1%40172.23.121.215.zip 

      Attachments

        Issue Links

          For Gerrit Dashboard: MB-53221
          # Subject Branch Project Status CR V

          Activity

            Build couchbase-server-8.0.0-1073 contains indexing commit 6400782 with commit message:
            MB-53221 Use copies of snapshot timestamp when computing restartTs

            build-team Couchbase Build Team added a comment - Build couchbase-server-8.0.0-1073 contains indexing commit 6400782 with commit message: MB-53221 Use copies of snapshot timestamp when computing restartTs

            Resolving this issue as the fix is in and validation steps for the fix are given as well

            varun.velamuri Varun Velamuri added a comment - Resolving this issue as the fix is in and validation steps for the fix are given as well
            pavan.pb Pavan PB added a comment -

            Verified on 6.6.5-10109. 

            Before the fix

            [root@sa2020 CBSE]# cat /opt/couchbase/var/lib/couchbase/logs/indexer.log | grep "handleRollback"
            2022-08-08T03:57:11.373-07:00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP -
            2022-08-08T03:57:11.383-07:00 [Info] StorageMgr::handleRollback latestSnapInfo SnapshotInfo: count:1000000 committed:false lastRollbackTs <nil>. Use latest snapshot.
            2022-08-08T03:57:11.409-07:00 [Info] StorageMgr::handleRollback Rollback Index: 1915666956871796050 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count:1000000 committed:false 
            2022-08-08T03:57:13.752-07:00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP -
            2022-08-08T03:57:13.763-07:00 [Info] StorageMgr::handleRollback Discarding Snapshot SnapshotInfo: count:1000000 committed:false. Need older than last used snapshot bucket: test1, vbuckets: 1024 Crc64: 5690975992183734229 snapType FORCE_COMMIT -
            2022-08-08T03:57:13.764-07:00 [Info] StorageMgr::handleRollback Discarding Snapshot SnapshotInfo: count:1000000 committed:false. Need older than last used snapshot bucket: test1, vbuckets: 1024 Crc64: 5690975992183734229 snapType FORCE_COMMIT -
            2022-08-08T03:57:13.765-07:00 [Info] StorageMgr::handleRollback Discarding Snapshot SnapshotInfo: count:1000000 committed:false. Need older than last used snapshot bucket: test1, vbuckets: 1024 Crc64: 5690975992183734229 snapType FORCE_COMMIT -
            2022-08-08T03:57:14.055-07:00 [Info] StorageMgr::handleRollback Rollback Index: 1915666956871796050 PartitionId: 0 SliceId: 0 To Zero 
            2022-08-08T03:57:14.258-07:00 [Info] StorageMgr::handleRollback Rollback Index: 1915666956871796050 PartitionId: 0 SliceId: 0 To Zero
            cat /opt/couchbase/var/lib/couchbase/logs/indexer.log | grep "Using Next snapshot"
            [root@sa2020 CBSE]#  

            After the fix

            2022-08-08T05:35:49.959-07:00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP -
            2022-08-08T05:35:49.962-07:00 [Info] StorageMgr::handleRollback 625429202321694066 latestSnapInfo SnapshotInfo: count:252090 committed:false lastRollbackTs <nil>. Use latest snapshot.
            2022-08-08T05:35:49.971-07:00 [Info] StorageMgr::handleRollback Rollback Index: 625429202321694066 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count:252090 committed:false 
            2022-08-08T05:35:52.135-07:00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP -
            2022-08-08T05:35:52.138-07:00 [Info] StorageMgr::handleRollback 625429202321694066 Unable to find a snapshot older than last used Snapshot SnapshotInfo: count:252090 committed:false. Use nil snapshot.
            2022-08-08T05:35:52.257-07:00 [Info] StorageMgr::handleRollback Rollback Index: 625429202321694066 PartitionId: 0 SliceId: 0 To Zero 
            2022-08-08T05:35:52.471-07:00 [Info] StorageMgr::handleRollback Rollback Index: 625429202321694066 PartitionId: 0 SliceId: 0 To Zero 
            2022-08-08T05:46:24.400-07:00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP -
            2022-08-08T05:46:24.405-07:00 [Info] StorageMgr::handleRollback 625429202321694066 latestSnapInfo SnapshotInfo: count:168501 committed:false lastRollbackTs <nil>. Use latest snapshot.
            2022-08-08T05:46:24.583-07:00 [Info] StorageMgr::handleRollback Rollback Index: 625429202321694066 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count:168501 committed:false 
            2022-08-08T05:46:51.332-07:00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP -
            2022-08-08T05:46:51.338-07:00 [Info] StorageMgr::handleRollback 625429202321694066 Discarding Already Used Snapshot SnapshotInfo: count:168501 committed:false. Using Next snapshot SnapshotInfo: count:168478 committed:false
            2022-08-08T05:46:51.409-07:00 [Info] StorageMgr::handleRollback Rollback Index: 625429202321694066 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count:168478 committed:false  

            The "Using Next snapshot" line is seen.

             

            Keeping this ticket open for validation of the fix on 7.1.2 builds. cc Balakumaran Gopal Ritam Sharma 

            pavan.pb Pavan PB added a comment - Verified on 6.6.5-10109.  Before the fix [root @sa2020 CBSE]# cat /opt/couchbase/var/lib/couchbase/logs/indexer.log | grep "handleRollback" 2022 - 08 -08T03: 57 : 11.373 - 07 : 00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP - 2022 - 08 -08T03: 57 : 11.383 - 07 : 00 [Info] StorageMgr::handleRollback latestSnapInfo SnapshotInfo: count: 1000000 committed: false lastRollbackTs <nil>. Use latest snapshot. 2022 - 08 -08T03: 57 : 11.409 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 1915666956871796050 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count: 1000000 committed: false   2022 - 08 -08T03: 57 : 13.752 - 07 : 00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP - 2022 - 08 -08T03: 57 : 13.763 - 07 : 00 [Info] StorageMgr::handleRollback Discarding Snapshot SnapshotInfo: count: 1000000 committed: false . Need older than last used snapshot bucket: test1, vbuckets: 1024 Crc64: 5690975992183734229 snapType FORCE_COMMIT - 2022 - 08 -08T03: 57 : 13.764 - 07 : 00 [Info] StorageMgr::handleRollback Discarding Snapshot SnapshotInfo: count: 1000000 committed: false . Need older than last used snapshot bucket: test1, vbuckets: 1024 Crc64: 5690975992183734229 snapType FORCE_COMMIT - 2022 - 08 -08T03: 57 : 13.765 - 07 : 00 [Info] StorageMgr::handleRollback Discarding Snapshot SnapshotInfo: count: 1000000 committed: false . Need older than last used snapshot bucket: test1, vbuckets: 1024 Crc64: 5690975992183734229 snapType FORCE_COMMIT - 2022 - 08 -08T03: 57 : 14.055 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 1915666956871796050 PartitionId: 0 SliceId: 0 To Zero  2022 - 08 -08T03: 57 : 14.258 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 1915666956871796050 PartitionId: 0 SliceId: 0 To Zero cat /opt/couchbase/var/lib/couchbase/logs/indexer.log | grep "Using Next snapshot" [root @sa2020 CBSE]#  After the fix 2022 - 08 -08T05: 35 : 49.959 - 07 : 00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP - 2022 - 08 -08T05: 35 : 49.962 - 07 : 00 [Info] StorageMgr::handleRollback 625429202321694066 latestSnapInfo SnapshotInfo: count: 252090 committed: false lastRollbackTs <nil>. Use latest snapshot. 2022 - 08 -08T05: 35 : 49.971 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 625429202321694066 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count: 252090 committed: false   2022 - 08 -08T05: 35 : 52.135 - 07 : 00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP - 2022 - 08 -08T05: 35 : 52.138 - 07 : 00 [Info] StorageMgr::handleRollback 625429202321694066 Unable to find a snapshot older than last used Snapshot SnapshotInfo: count: 252090 committed: false . Use nil snapshot. 2022 - 08 -08T05: 35 : 52.257 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 625429202321694066 PartitionId: 0 SliceId: 0 To Zero  2022 - 08 -08T05: 35 : 52.471 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 625429202321694066 PartitionId: 0 SliceId: 0 To Zero  2022 - 08 -08T05: 46 : 24.400 - 07 : 00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP - 2022 - 08 -08T05: 46 : 24.405 - 07 : 00 [Info] StorageMgr::handleRollback 625429202321694066 latestSnapInfo SnapshotInfo: count: 168501 committed: false lastRollbackTs <nil>. Use latest snapshot. 2022 - 08 -08T05: 46 : 24.583 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 625429202321694066 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count: 168501 committed: false   2022 - 08 -08T05: 46 : 51.332 - 07 : 00 [Info] StorageMgr::handleRollback rollbackTs is bucket: test1, vbuckets: 1024 Crc64: 0 snapType NO_SNAP - 2022 - 08 -08T05: 46 : 51.338 - 07 : 00 [Info] StorageMgr::handleRollback 625429202321694066 Discarding Already Used Snapshot SnapshotInfo: count: 168501 committed: false . Using Next snapshot SnapshotInfo: count: 168478 committed: false 2022 - 08 -08T05: 46 : 51.409 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 625429202321694066 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count: 168478 committed: false   The "Using Next snapshot" line is seen.   Keeping this ticket open for validation of the fix on 7.1.2 builds. cc Balakumaran Gopal Ritam Sharma  
            pavan.pb Pavan PB added a comment -

            Validated the fix on 7.1.2-3419 

             

            2022-08-09T23:45:43.364-07:00 [Info] StorageMgr::handleRollback Rollback Index: 9834120264697893887 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count:3000000 committed:false 
            2022-08-09T23:45:46.113-07:00 [Info] StorageMgr::handleRollback MAINT_STREAM default rollbackTs bucket: default, scopeId: , collectionId: , vbuckets: 1024 Crc64: 0 snapType NO_SNAP OpenOSOSnap false -
            2022-08-09T23:45:46.119-07:00 [Info] StorageMgr::handleRollback 9834120264697893887 Discarding Already Used Snapshot SnapshotInfo: count:3000000 committed:false. Using Next snapshot SnapshotInfo: count:3000000 committed:false
            2022-08-09T23:45:46.217-07:00 [Info] StorageMgr::handleRollback Rollback Index: 9834120264697893887 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count:3000000 committed:false 
            2022-08-09T23:45:48.985-07:00 [Info] StorageMgr::handleRollback MAINT_STREAM default rollbackTs bucket: default, scopeId: , collectionId: , vbuckets: 1024 Crc64: 0 snapType NO_SNAP OpenOSOSnap false -
            2022-08-09T23:45:48.989-07:00 [Info] StorageMgr::handleRollback 9834120264697893887 Unable to find a snapshot older than last used Snapshot SnapshotInfo: count:3000000 committed:false. Use nil snapshot.
            2022-08-09T23:45:49.351-07:00 [Info] StorageMgr::handleRollback Rollback Index: 9834120264697893887 PartitionId: 0 SliceId: 0 To Zero 
            2022-08-09T23:45:49.561-07:00 [Info] StorageMgr::handleRollback Rollback Index: 9834120264697893887 PartitionId: 0 SliceId: 0 To Zero  

            Keeping this ticket open for validation on 7.2.0 and 8.0.0 builds. cc Chanabasappa Ghali 

             

            pavan.pb Pavan PB added a comment - Validated the fix on 7.1.2-3419    2022 - 08 -09T23: 45 : 43.364 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 9834120264697893887 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count: 3000000 committed: false   2022 - 08 -09T23: 45 : 46.113 - 07 : 00 [Info] StorageMgr::handleRollback MAINT_STREAM default rollbackTs bucket: default , scopeId: , collectionId: , vbuckets: 1024 Crc64: 0 snapType NO_SNAP OpenOSOSnap false - 2022 - 08 -09T23: 45 : 46.119 - 07 : 00 [Info] StorageMgr::handleRollback 9834120264697893887 Discarding Already Used Snapshot SnapshotInfo: count: 3000000 committed: false . Using Next snapshot SnapshotInfo: count: 3000000 committed: false 2022 - 08 -09T23: 45 : 46.217 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 9834120264697893887 PartitionId: 0 SliceId: 0 To Snapshot SnapshotInfo: count: 3000000 committed: false   2022 - 08 -09T23: 45 : 48.985 - 07 : 00 [Info] StorageMgr::handleRollback MAINT_STREAM default rollbackTs bucket: default , scopeId: , collectionId: , vbuckets: 1024 Crc64: 0 snapType NO_SNAP OpenOSOSnap false - 2022 - 08 -09T23: 45 : 48.989 - 07 : 00 [Info] StorageMgr::handleRollback 9834120264697893887 Unable to find a snapshot older than last used Snapshot SnapshotInfo: count: 3000000 committed: false . Use nil snapshot. 2022 - 08 -09T23: 45 : 49.351 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 9834120264697893887 PartitionId: 0 SliceId: 0 To Zero  2022 - 08 -09T23: 45 : 49.561 - 07 : 00 [Info] StorageMgr::handleRollback Rollback Index: 9834120264697893887 PartitionId: 0 SliceId: 0 To Zero  Keeping this ticket open for validation on 7.2.0 and 8.0.0 builds. cc Chanabasappa Ghali    

            Build couchbase-server-7.2.0-5000 contains indexing commit 108d0b9 with commit message:
            MB-53221 Use copies of snapshot timestamp when computing restartTs

            build-team Couchbase Build Team added a comment - Build couchbase-server-7.2.0-5000 contains indexing commit 108d0b9 with commit message: MB-53221 Use copies of snapshot timestamp when computing restartTs

            People

              pavan.pb Pavan PB
              pavan.pb Pavan PB
              Votes:
              0 Vote for this issue
              Watchers:
              9 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  PagerDuty