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

[System Test] : Disconnect link local caused JVM halting with status 105

    XMLWordPrintable

Details

    Description

      Build : 6.5.0-3748
      Test : -test tests/analytics/test_analytics_rebalance.yml -scope tests/analytics/scope_analytics_rebalance.yml
      Scale : 4
      Iteration :

      In the system test, after a step where link is disconnected, there is a crash observed on 172.23.96.214

      Disconnect link local completed on 2019-07-16T21:15:45. Just around this time, on 172.23.96.214 there was a crash observed. This is different from MB-35139.

      2019-07-16T21:15:28.083-07:00 ERRO CBAS.adapter.ShadowStatesRequest [Executor-392:5479755454fcdf44fb74766ee393d5f1] Index {"class" : "LSMBTree", "dir" : "/data/idx/@analytics/v_iodevice_4/storage/partition_28/Default/ds2/6/ds2", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"UNREADABLE_UNWRITABLE", "writers":0, "readers":1, "pendingFlushes":0, "id":"[16,16]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[17,17]"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":0} with modified memory component has no DCP state
      		 
      2019-07-16T21:15:29.051-07:00 FATA CBAS.util.ExitUtil [Executor-392:5479755454fcdf44fb74766ee393d5f1] JVM halting with status 105; thread dump at halt: 
      "main" [tid=1 state=WAITING lock=java.util.concurrent.Semaphore$NonfairSync@56bf2346]
      		 
      	at java.base@11.0.1/jdk.internal.misc.Unsafe.park(Native Method)
      		 
      	at java.base@11.0.1/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
      		 
      	at java.base@11.0.1/java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:885)
      		 
      	at java.base@11.0.1/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1039)
      		 
      	at java.base@11.0.1/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1345)
      		 
      	at java.base@11.0.1/java.util.concurrent.Semaphore.acquire(Semaphore.java:318)
      		 
      	at app//com.couchbase.analytics.control.AnalyticsDriver.main(AnalyticsDriver.java:118)

      The analytics warn logs have some more details:

      2019-07-16T21:15:25.086-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A FLUSH produced an empty component
      		 
      2019-07-16T21:15:25.126-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A MERGE produced an empty component
      		 
      2019-07-16T21:15:25.225-07:00 WARN CBAS.impls.ComponentReplacementContext [Executor-162:5479755454fcdf44fb74766ee393d5f1:JID:3.6370:TAID:TID:ANID:ODID:2:0:4:0:SuperActivityOperatorNodePushable] memory component [16,16] was flushed and merged before search cursor replaces it
      		 
      2019-07-16T21:15:25.232-07:00 WARN CBAS.runtime.FullRollbackOperatorDescriptor [Executor-182:5479755454fcdf44fb74766ee393d5f1:JID:3.6474:TAID:TID:ANID:ODID:0:0:2:0:SuperActivityOperatorNodePushable] Fully rolledback dataset {"nodeGroupName":"Default.ds2_6","hints":{},"datasetName":"ds2","recordTypeDataverseName":"Metadata","datasetDetails":"org.apache.asterix.metadata.entities.InternalDatasetDetails@4642c055","pendingOp":"Pending No Operation","metaTypeName":"DCPMeta","rebalanceCount":6,"datasetId":"102","compactionPolicyFactory":"prefix","compactionPolicyProperties":{"max-mergable-component-size":"1073741824","max-tolerance-component-count":"5"},"metaTypeDataverseName":"Metadata","dataverseName":"Default","datasetType":"INTERNAL","compressionScheme":"snappy","recordTypeName":"AnyObject"} partition 4
      		 
      2019-07-16T21:15:25.242-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A FLUSH produced an empty component
      		 
      2019-07-16T21:15:25.250-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A MERGE produced an empty component
      		 
      2019-07-16T21:15:25.317-07:00 WARN CBAS.runtime.FullRollbackOperatorDescriptor [Executor-182:5479755454fcdf44fb74766ee393d5f1:JID:3.6474:TAID:TID:ANID:ODID:0:0:2:0:SuperActivityOperatorNodePushable] Fully rolledback dataset {"nodeGroupName":"Default.ds2_6","hints":{},"datasetName":"ds2","recordTypeDataverseName":"Metadata","datasetDetails":"org.apache.asterix.metadata.entities.InternalDatasetDetails@4642c055","pendingOp":"Pending No Operation","metaTypeName":"DCPMeta","rebalanceCount":6,"datasetId":"102","compactionPolicyFactory":"prefix","compactionPolicyProperties":{"max-mergable-component-size":"1073741824","max-tolerance-component-count":"5"},"metaTypeDataverseName":"Metadata","dataverseName":"Default","datasetType":"INTERNAL","compressionScheme":"snappy","recordTypeName":"AnyObject"} partition 5
      		 
      2019-07-16T21:15:25.328-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A FLUSH produced an empty component
      		 
      2019-07-16T21:15:25.356-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A MERGE produced an empty component
      		 
      2019-07-16T21:15:25.408-07:00 WARN CBAS.runtime.FullRollbackOperatorDescriptor [Executor-182:5479755454fcdf44fb74766ee393d5f1:JID:3.6474:TAID:TID:ANID:ODID:0:0:2:0:SuperActivityOperatorNodePushable] Fully rolledback dataset {"nodeGroupName":"Default.ds2_6","hints":{},"datasetName":"ds2","recordTypeDataverseName":"Metadata","datasetDetails":"org.apache.asterix.metadata.entities.InternalDatasetDetails@4642c055","pendingOp":"Pending No Operation","metaTypeName":"DCPMeta","rebalanceCount":6,"datasetId":"102","compactionPolicyFactory":"prefix","compactionPolicyProperties":{"max-mergable-component-size":"1073741824","max-tolerance-component-count":"5"},"metaTypeDataverseName":"Metadata","dataverseName":"Default","datasetType":"INTERNAL","compressionScheme":"snappy","recordTypeName":"AnyObject"} partition 6
      		 
      2019-07-16T21:15:25.419-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A FLUSH produced an empty component
      		 
      2019-07-16T21:15:25.453-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A MERGE produced an empty component
      		 
      2019-07-16T21:15:25.536-07:00 WARN CBAS.runtime.FullRollbackOperatorDescriptor [Executor-182:5479755454fcdf44fb74766ee393d5f1:JID:3.6474:TAID:TID:ANID:ODID:0:0:2:0:SuperActivityOperatorNodePushable] Fully rolledback dataset {"nodeGroupName":"Default.ds2_6","hints":{},"datasetName":"ds2","recordTypeDataverseName":"Metadata","datasetDetails":"org.apache.asterix.metadata.entities.InternalDatasetDetails@4642c055","pendingOp":"Pending No Operation","metaTypeName":"DCPMeta","rebalanceCount":6,"datasetId":"102","compactionPolicyFactory":"prefix","compactionPolicyProperties":{"max-mergable-component-size":"1073741824","max-tolerance-component-count":"5"},"metaTypeDataverseName":"Metadata","dataverseName":"Default","datasetType":"INTERNAL","compressionScheme":"snappy","recordTypeName":"AnyObject"} partition 7
      		 
      2019-07-16T21:15:25.551-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A FLUSH produced an empty component
      		 
      2019-07-16T21:15:25.622-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A MERGE produced an empty component
      		 
      2019-07-16T21:15:25.754-07:00 WARN CBAS.runtime.FullRollbackOperatorDescriptor [Executor-182:5479755454fcdf44fb74766ee393d5f1:JID:3.6474:TAID:TID:ANID:ODID:0:0:2:0:SuperActivityOperatorNodePushable] Fully rolledback dataset {"nodeGroupName":"Default.ds2_6","hints":{},"datasetName":"ds2","recordTypeDataverseName":"Metadata","datasetDetails":"org.apache.asterix.metadata.entities.InternalDatasetDetails@4642c055","pendingOp":"Pending No Operation","metaTypeName":"DCPMeta","rebalanceCount":6,"datasetId":"102","compactionPolicyFactory":"prefix","compactionPolicyProperties":{"max-mergable-component-size":"1073741824","max-tolerance-component-count":"5"},"metaTypeDataverseName":"Metadata","dataverseName":"Default","datasetType":"INTERNAL","compressionScheme":"snappy","recordTypeName":"AnyObject"} partition 8
      		 
      2019-07-16T21:15:25.764-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A FLUSH produced an empty component
      		 
      2019-07-16T21:15:25.837-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A MERGE produced an empty component
      		 
      2019-07-16T21:15:25.878-07:00 WARN CBAS.runtime.FullRollbackOperatorDescriptor [Executor-182:5479755454fcdf44fb74766ee393d5f1:JID:3.6474:TAID:TID:ANID:ODID:0:0:2:0:SuperActivityOperatorNodePushable] Fully rolledback dataset {"nodeGroupName":"Default.ds2_6","hints":{},"datasetName":"ds2","recordTypeDataverseName":"Metadata","datasetDetails":"org.apache.asterix.metadata.entities.InternalDatasetDetails@4642c055","pendingOp":"Pending No Operation","metaTypeName":"DCPMeta","rebalanceCount":6,"datasetId":"102","compactionPolicyFactory":"prefix","compactionPolicyProperties":{"max-mergable-component-size":"1073741824","max-tolerance-component-count":"5"},"metaTypeDataverseName":"Metadata","dataverseName":"Default","datasetType":"INTERNAL","compressionScheme":"snappy","recordTypeName":"AnyObject"} partition 9
      		 
      2019-07-16T21:15:25.888-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A FLUSH produced an empty component
      		 
      2019-07-16T21:15:25.900-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A MERGE produced an empty component
      		 
      2019-07-16T21:15:25.961-07:00 WARN CBAS.runtime.FullRollbackOperatorDescriptor [Executor-182:5479755454fcdf44fb74766ee393d5f1:JID:3.6474:TAID:TID:ANID:ODID:0:0:2:0:SuperActivityOperatorNodePushable] Fully rolledback dataset {"nodeGroupName":"Default.ds2_6","hints":{},"datasetName":"ds2","recordTypeDataverseName":"Metadata","datasetDetails":"org.apache.asterix.metadata.entities.InternalDatasetDetails@4642c055","pendingOp":"Pending No Operation","metaTypeName":"DCPMeta","rebalanceCount":6,"datasetId":"102","compactionPolicyFactory":"prefix","compactionPolicyProperties":{"max-mergable-component-size":"1073741824","max-tolerance-component-count":"5"},"metaTypeDataverseName":"Metadata","dataverseName":"Default","datasetType":"INTERNAL","compressionScheme":"snappy","recordTypeName":"AnyObject"} partition 10
      		 
      2019-07-16T21:15:25.974-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A FLUSH produced an empty component
      		 
      2019-07-16T21:15:25.992-07:00 WARN CBAS.metadata.MaintainDcpCallbackFactory [Executor-413:5479755454fcdf44fb74766ee393d5f1] A MERGE produced an empty component
      		 
      2019-07-16T21:15:26.145-07:00 WARN CBAS.runtime.FullRollbackOperatorDescriptor [Executor-182:5479755454fcdf44fb74766ee393d5f1:JID:3.6474:TAID:TID:ANID:ODID:0:0:2:0:SuperActivityOperatorNodePushable] Fully rolledback dataset {"nodeGroupName":"Default.ds2_6","hints":{},"datasetName":"ds2","recordTypeDataverseName":"Metadata","datasetDetails":"org.apache.asterix.metadata.entities.InternalDatasetDetails@4642c055","pendingOp":"Pending No Operation","metaTypeName":"DCPMeta","rebalanceCount":6,"datasetId":"102","compactionPolicyFactory":"prefix","compactionPolicyProperties":{"max-mergable-component-size":"1073741824","max-tolerance-component-count":"5"},"metaTypeDataverseName":"Metadata","dataverseName":"Default","datasetType":"INTERNAL","compressionScheme":"snappy","recordTypeName":"AnyObject"} partition 11
      		 
      2019-07-16T21:15:28.083-07:00 ERRO CBAS.adapter.ShadowStatesRequest [Executor-392:5479755454fcdf44fb74766ee393d5f1] Index {"class" : "LSMBTree", "dir" : "/data/idx/@analytics/v_iodevice_4/storage/partition_28/Default/ds2/6/ds2", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"UNREADABLE_UNWRITABLE", "writers":0, "readers":1, "pendingFlushes":0, "id":"[16,16]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[17,17]"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":0} with modified memory component has no DCP state
      		 
      2019-07-16T21:15:29.051-07:00 FATA CBAS.util.ExitUtil [Executor-392:5479755454fcdf44fb74766ee393d5f1] JVM halting with status 105; thread dump at halt:

      Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          People

            mihir.kamdar Mihir Kamdar (Inactive)
            mihir.kamdar Mihir Kamdar (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Gerrit Reviews

                There are no open Gerrit changes

                PagerDuty