Hi Ian,
Please find the NC log in the attachment.
Actually I was able to set it up using Ansible
<https://ci.apache.org/projects/asterixdb/ansible.html>, which is a more
clean way than using NCService. But it would be still great to figure out
what happened with NCService option.
Thanks,
Tin
On Sun, Feb 21, 2021 at 1:36 AM Ian Maxon <[email protected]> wrote:
> Can you post the NC log? That should show why it failed to start.
>
> On Sat, Feb 20, 2021 at 5:04 PM Tin Vu <[email protected]> wrote:
> >
> > Hi all,
> >
> > I'm trying to install AsterixDB 0.9.6 on my cluster. I'm following the
> tutorial at:
> https://ci.apache.org/projects/asterixdb/ncservice.html#Multi_machine
> >
> > Currently, I'm able to start NCService on each node. However, when I
> start the cluster controller using the following command:
> > ```
> > bin/asterixcc -config-file cc.conf > cc.log 2>&1 &
> > ```
> > I always got the following error:
> > ```
> > 16:57:05.115 [Executor-12:ClusterController] ERROR
> org.apache.asterix.app.replication.NcLifecycleCoordinator - Node
> asterix_nc1 failed to complete startup
> > org.apache.hyracks.api.exceptions.HyracksDataException: attempt to
> create metadata index Dataverse. Index should already exist
> > ```
> >
> > Have any of you got into this problem before? If so, I would appreciate
> it if you can give me a hint to solve it. I attached the config file for
> reference.
> >
> > Thanks,
> >
> > Tin
>
15:50:45.481 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Setting uncaught exception handler org.apache.hyracks.api.lifecycle.LifeCycleComponentManager@5f9b2141
15:50:45.507 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Starting NodeControllerService
15:50:45.587 [main] INFO org.apache.hyracks.util.trace.Tracer - Initialize Tracer org.apache.hyracks.util.trace.Tracer.Traces.asterix_nc1
15:50:45.593 [main] INFO org.apache.hyracks.util.trace.Tracer - Set categories for Tracer org.apache.hyracks.util.trace.Tracer.Traces.asterix_nc1 to []
15:50:45.594 [main] INFO org.apache.hyracks.util.LoggingConfigUtil - Setting org.apache.hyracks log level to INFO
15:50:45.595 [main] INFO org.apache.hyracks.util.LoggingConfigUtil - Setting org.apache.asterix log level to INFO
15:50:45.598 [main] INFO org.apache.asterix.hyracks.bootstrap.ApplicationConfigurator - Found JRE version 1.8.0_131
15:50:45.910 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Starting Asterix node controller: asterix_nc1
15:50:46.100 [main] INFO org.apache.asterix.app.nc.TransactionSubsystem - Checkpoint Properties: {"class" : "CheckpointProperties", "checkpoint-dir-path" : "data/red/txnlog", "lsn-threshold" : 67108864, "poll-frequency" : 120, "history-to-keep" : 2, "dataset-checkpoint-interval" : 3600}
15:50:46.104 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Checkpoint directory = data/red/txnlog
15:50:46.104 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Checkpoint directory data/red/txnlog/ didn't exist. Creating one
15:50:46.104 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
15:50:46.105 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned empty
15:50:46.111 [main] INFO org.apache.asterix.transaction.management.service.logging.LogManager - the log dir (data/red/txnlog) is empty. returning empty list
15:50:46.148 [main] INFO org.apache.asterix.transaction.management.service.logging.LogManager - Created log file data/red/txnlog/transaction_log_0
15:50:46.148 [main] INFO org.apache.asterix.transaction.management.service.logging.LogManager - initializing log anchor with log file Id: 0 at offset: 0
15:50:46.148 [main] INFO org.apache.asterix.transaction.management.service.logging.LogManager - LogManager starts logging in LSN: 0
15:50:46.152 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
15:50:46.152 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned empty
15:50:46.153 [main] INFO org.apache.asterix.app.nc.RecoveryManager - The checkpoint file doesn't exist: systemState = PERMANENT_DATA_LOSS
15:50:46.153 [main] WARN org.apache.asterix.app.nc.NCAppRuntimeContext - Deleting the storage dir. initialRun = false, systemState = PERMANENT_DATA_LOSS
15:50:46.153 [main] INFO org.apache.asterix.app.nc.NCAppRuntimeContext - The value of maxConcurrentFlushes is not provided. Setting maxConcurrentFlushes = 1.
15:50:46.355 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
15:50:46.355 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned empty
15:50:46.355 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
15:50:46.355 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned empty
15:50:46.356 [main] INFO org.apache.asterix.app.nc.RecoveryManager - The checkpoint file doesn't exist: systemState = PERMANENT_DATA_LOSS
15:50:46.356 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - System state: PERMANENT_DATA_LOSS
15:50:46.356 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Node ID: asterix_nc1
15:50:46.356 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Stores: {asterix_nc1=[data/red/storage], asterix_nc2=[data/blue/storage]}
15:50:46.489 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - addCc: /127.0.0.1:1099
15:50:46.520 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Registering with Cluster Controller ClusterControllerRemoteProxy [/127.0.0.1:1099]
15:50:46.660 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Registering with Cluster Controller ClusterControllerRemoteProxy [/127.0.0.1:1099] completed
15:50:46.661 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Started NodeControllerService
15:50:46.661 [Worker:asterix_nc1] INFO org.apache.hyracks.control.nc.work.AbortAllJobsWork - Aborting all tasks for controller CC:0
15:50:46.662 [main] INFO org.apache.hyracks.util.ExitUtil - successfully registered shutdown hook Thread[ShutdownHook-asterix_nc1,5,main]
15:50:46.667 [Executor-6:asterix_nc1] INFO org.apache.hyracks.control.nc.work.EnsureAllCcTasksCompleted - Ensuring all tasks of CC CC:0 have completed
15:50:46.673 [Executor-6:asterix_nc1] INFO org.apache.hyracks.control.nc.work.EnsureAllCcTasksCompleted - all tasks of CC CC:0 have completed
15:50:46.821 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
15:50:46.822 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned empty
15:50:46.822 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.nc.RecoveryManager - The checkpoint file doesn't exist: systemState = PERMANENT_DATA_LOSS
15:50:46.863 [Worker:asterix_nc1] INFO org.apache.asterix.messaging.NCMessageBroker - Received message: org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage@75ba57b9
15:50:46.864 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "UpdateNodeStatusTask" }
15:50:46.864 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Completed startup task: { "class" : "UpdateNodeStatusTask" }
15:50:46.864 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "MetadataBootstrapTask" }
15:50:46.864 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
15:50:46.865 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned empty
15:50:46.865 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.nc.RecoveryManager - The checkpoint file doesn't exist: systemState = PERMANENT_DATA_LOSS
15:50:46.865 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.nc.NCAppRuntimeContext - Bootstrapping metadata
15:50:46.912 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.CachingTxnIdFactory - block exhausted; obtaining new block from supplier
15:50:46.921 [Worker:asterix_nc1] INFO org.apache.asterix.messaging.NCMessageBroker - Received message: TxnIdBlockResponse
15:50:48.152 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.bootstrap.MetadataBootstrap - Finished enlistment of metadata B-trees in new universe
15:50:48.200 [Executor-6:asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Registered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataverse/0/Dataverse", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":0, "current-memory-component":0} to the global VBC
15:50:48.251 [Executor-6:asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Registered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataset/0/Dataset", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":0, "current-memory-component":0} to the global VBC
15:50:48.255 [Executor-6:asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Registered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Index/0/Index", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":0, "current-memory-component":0} to the global VBC
15:50:48.286 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.bootstrap.MetadataBootstrap - Finished inserting initial datasets.
15:50:48.290 [Executor-6:asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Registered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Datatype/0/Datatype", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":0, "current-memory-component":0} to the global VBC
15:50:48.364 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.bootstrap.MetadataBootstrap - Finished inserting initial datatypes.
15:50:48.366 [Executor-6:asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Registered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Node/0/Node", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":0, "current-memory-component":0} to the global VBC
15:50:48.369 [Executor-6:asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Registered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Nodegroup/0/Nodegroup", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":0, "current-memory-component":0} to the global VBC
15:50:48.375 [Executor-6:asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Registered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/DatasourceAdapter/0/DatasourceAdapter", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":0, "current-memory-component":0} to the global VBC
15:50:48.376 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.bootstrap.MetadataBootstrap - Finished inserting built-in adapters.
15:50:48.379 [Executor-6:asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Registered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/FeedPolicy/0/FeedPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":0, "current-memory-component":0} to the global VBC
15:50:48.380 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.feeds.BuiltinFeedPolicies - Finished adding built-in feed policies.
15:50:48.382 [Executor-6:asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Registered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/CompactionPolicy/0/CompactionPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":0, "current-memory-component":0} to the global VBC
15:50:48.384 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.bootstrap.MetadataBootstrap - Finished creating metadata B-trees.
15:50:48.456 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.bootstrap.MetadataBootstrap - Starting DDL recovery ...
15:50:48.483 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.bootstrap.MetadataBootstrap - Completed DDL recovery.
15:50:48.483 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.nc.NCAppRuntimeContext - Metadata node bound
15:50:48.483 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Completed startup task: { "class" : "MetadataBootstrapTask" }
15:50:48.483 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "CheckpointTask" }
15:50:48.483 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.CheckpointManager - Starting sharp checkpoint...
15:50:48.549 [Executor-8:asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Flushing component with id: [1,1] in the index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataverse/0/Dataverse", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"READABLE_UNWRITABLE_FLUSHING", "writers":0, "readers":1, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":1}
15:50:48.746 [Executor-8:asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Flushing component with id: [1,1] in the index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataset/0/Dataset", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"READABLE_UNWRITABLE_FLUSHING", "writers":0, "readers":1, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":1}
15:50:48.978 [Executor-8:asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Flushing component with id: [1,1] in the index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Datatype/0/Datatype", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"READABLE_UNWRITABLE_FLUSHING", "writers":0, "readers":1, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":1}
15:50:49.145 [Executor-8:asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Flushing component with id: [1,1] in the index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Index/0/Index", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"READABLE_UNWRITABLE_FLUSHING", "writers":0, "readers":1, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":1}
15:50:49.353 [Executor-8:asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Flushing component with id: [1,1] in the index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Node/0/Node", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"READABLE_UNWRITABLE_FLUSHING", "writers":0, "readers":1, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":1}
15:50:49.497 [Executor-8:asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Flushing component with id: [1,1] in the index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Nodegroup/0/Nodegroup", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"READABLE_UNWRITABLE_FLUSHING", "writers":0, "readers":1, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":1}
15:50:49.680 [Executor-8:asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Flushing component with id: [1,1] in the index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/DatasourceAdapter/0/DatasourceAdapter", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"READABLE_UNWRITABLE_FLUSHING", "writers":0, "readers":1, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":1}
15:50:49.839 [Executor-8:asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Flushing component with id: [1,1] in the index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/FeedPolicy/0/FeedPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"READABLE_UNWRITABLE_FLUSHING", "writers":0, "readers":1, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":1}
15:50:50.089 [Executor-8:asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Flushing component with id: [1,1] in the index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/CompactionPolicy/0/CompactionPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"READABLE_UNWRITABLE_FLUSHING", "writers":0, "readers":1, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 0, "num-scheduled-flushes":1, "current-memory-component":1}
15:50:50.216 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned empty
15:50:50.217 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Persisting checkpoint file to /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/txnlog/checkpoint_0 which doesn't exist yet
15:50:50.257 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Completed persisting checkpoint file to /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/txnlog/checkpoint_0 which now exists
15:50:50.257 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [data/red/txnlog/checkpoint_0]
15:50:50.257 [Executor-6:asterix_nc1] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/txnlog/checkpoint_0
15:50:50.258 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.logging.LogManager - Terminating LogFlusher thread ...
15:50:50.260 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.logging.LogManager - LogFlusher thread is terminated.
15:50:50.260 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.logging.LogManager - closing current log file with id(0)
15:50:50.261 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.logging.LogManager - Created log file data/red/txnlog/transaction_log_1
15:50:50.261 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.logging.LogManager - Deleted log file /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/txnlog/transaction_log_0
15:50:50.270 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.logging.LogManager - initializing log anchor with log file Id: 1 at offset: 0
15:50:50.270 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.logging.LogManager - LogManager starts logging in LSN: 268435456
15:50:50.270 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.CheckpointManager - Completed sharp checkpoint.
15:50:50.271 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Completed startup task: { "class" : "CheckpointTask" }
15:50:50.271 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "StartLifecycleComponentsTask" }
15:50:50.271 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.nc.task.StartLifecycleComponentsTask - Starting lifecycle components
15:50:50.271 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.nc.task.StartLifecycleComponentsTask - Coredump directory for NC is: data/red/coredump
15:50:50.271 [Executor-6:asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - LifecycleComponentManager configured org.apache.hyracks.api.lifecycle.LifeCycleComponentManager@5f9b2141
15:50:50.271 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.nc.task.StartLifecycleComponentsTask - Configured:org.apache.hyracks.api.lifecycle.LifeCycleComponentManager@5f9b2141
15:50:50.274 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Completed startup task: { "class" : "StartLifecycleComponentsTask" }
15:50:50.274 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "ExportMetadataNodeTask", "export-stub" : true }
15:50:50.305 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Completed startup task: { "class" : "ExportMetadataNodeTask", "export-stub" : true }
15:50:50.305 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "BindMetadataNodeTask" }
15:50:50.358 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Completed startup task: { "class" : "BindMetadataNodeTask" }
15:50:50.358 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "UpdateNodeStatusTask" }
15:50:50.358 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Completed startup task: { "class" : "UpdateNodeStatusTask" }
15:54:19.308 [ShutdownWatchdog] INFO org.apache.hyracks.util.ExitUtil - starting shutdown watchdog- system will halt if shutdown is not completed within 600 seconds
15:54:19.307 [JVM exit thread] WARN org.apache.hyracks.util.ExitUtil - JVM exiting with status 99; bye!
java.lang.Throwable: exit callstack
at org.apache.hyracks.util.ExitUtil.exit(ExitUtil.java:89) ~[hyracks-util-0.3.6.jar:0.3.6]
at org.apache.hyracks.control.nc.task.ShutdownTask.run(ShutdownTask.java:36) ~[hyracks-control-nc-0.3.6.jar:0.3.6]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_131]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_131]
at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_131]
15:54:19.317 [JVM exit thread] INFO org.apache.hyracks.util.ExitUtil - the following (2) shutdown hooks have been registered: {Thread[Thread-0,5,main]=Thread[Thread-0,5,main], Thread[ShutdownHook-asterix_nc1,5,main]=Thread[ShutdownHook-asterix_nc1,5,main]}
15:54:19.317 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.control.common.ControllerShutdownHook - Shutdown hook called
15:54:19.318 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.control.nc.NodeControllerService - Stopping NodeControllerService
15:54:19.318 [ShutdownHook-asterix_nc1] WARN org.apache.asterix.active.ActiveManager - Shutting down ActiveManager on node asterix_nc1
15:54:19.323 [ShutdownHook-asterix_nc1] WARN org.apache.asterix.active.ActiveManager - Shutdown ActiveManager on node asterix_nc1 complete
15:54:19.324 [Executor-5:asterix_nc1] WARN org.apache.hyracks.control.nc.result.ResultPartitionManager - Result cleaner thread interrupted, shutting down.
15:54:19.324 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Stopping Asterix node controller: asterix_nc1
15:54:21.378 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Attempting to stop org.apache.hyracks.api.lifecycle.LifeCycleComponentManager@5f9b2141
15:54:21.378 [ShutdownHook-asterix_nc1] ERROR org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Stopping instance
15:54:21.378 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Stopping component instance org.apache.asterix.external.library.ExternalLibraryManager; dump state: false, dump path: null
15:54:21.378 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Stopping component instance org.apache.asterix.transaction.management.service.recovery.CheckpointManager; dump state: false, dump path: null
15:54:21.379 [Checkpoint Thread (51)] INFO org.apache.asterix.transaction.management.service.recovery.CheckpointThread - Checkpoint thread interrupted
java.lang.InterruptedException: sleep interrupted
at java.lang.Thread.sleep(Native Method) ~[?:1.8.0_131]
at org.apache.asterix.transaction.management.service.recovery.CheckpointThread.run(CheckpointThread.java:59) [asterix-transactions-0.9.6.jar:0.9.6]
15:54:21.380 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Stopping component instance org.apache.asterix.transaction.management.service.locking.ConcurrentLockManager; dump state: false, dump path: null
15:54:21.380 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Stopping component instance org.apache.asterix.transaction.management.service.transaction.TransactionManager; dump state: false, dump path: null
15:54:21.380 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Stopping component instance org.apache.asterix.common.context.DatasetLifecycleManager; dump state: false, dump path: null
15:54:21.461 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.PrimaryIndexOperationTracker - Primary index on dataset 1 and partition 0 is empty... skipping flush
15:54:21.503 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataverse/0/Dataverse", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. STARTED
15:54:21.504 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the disk components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataverse/0/Dataverse", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:21.506 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deallocating memory components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataverse/0/Dataverse", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:21.519 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Unregistered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataverse/0/Dataverse", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1} to the global VBC
15:54:21.531 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataverse/0/Dataverse", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. COMPLETED
15:54:21.554 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.PrimaryIndexOperationTracker - Primary index on dataset 2 and partition 0 is empty... skipping flush
15:54:21.595 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataset/0/Dataset", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. STARTED
15:54:21.595 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the disk components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataset/0/Dataset", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:21.597 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deallocating memory components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataset/0/Dataset", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:21.610 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Unregistered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataset/0/Dataset", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1} to the global VBC
15:54:21.622 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Dataset/0/Dataset", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. COMPLETED
15:54:21.642 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.PrimaryIndexOperationTracker - Primary index on dataset 3 and partition 0 is empty... skipping flush
15:54:21.682 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Datatype/0/Datatype", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. STARTED
15:54:21.683 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the disk components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Datatype/0/Datatype", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:21.684 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deallocating memory components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Datatype/0/Datatype", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:21.698 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Unregistered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Datatype/0/Datatype", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1} to the global VBC
15:54:21.711 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Datatype/0/Datatype", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. COMPLETED
15:54:21.727 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.PrimaryIndexOperationTracker - Primary index on dataset 4 and partition 0 is empty... skipping flush
15:54:21.771 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Index/0/Index", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. STARTED
15:54:21.771 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the disk components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Index/0/Index", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:21.772 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deallocating memory components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Index/0/Index", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:21.783 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Unregistered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Index/0/Index", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1} to the global VBC
15:54:21.793 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Index/0/Index", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. COMPLETED
15:54:21.816 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.PrimaryIndexOperationTracker - Primary index on dataset 5 and partition 0 is empty... skipping flush
15:54:21.860 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Node/0/Node", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. STARTED
15:54:21.860 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the disk components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Node/0/Node", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:21.861 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deallocating memory components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Node/0/Node", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:21.876 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Unregistered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Node/0/Node", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1} to the global VBC
15:54:21.888 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Node/0/Node", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. COMPLETED
15:54:21.919 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.PrimaryIndexOperationTracker - Primary index on dataset 6 and partition 0 is empty... skipping flush
15:54:22.009 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Nodegroup/0/Nodegroup", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. STARTED
15:54:22.010 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the disk components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Nodegroup/0/Nodegroup", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:22.011 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deallocating memory components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Nodegroup/0/Nodegroup", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:22.024 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Unregistered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Nodegroup/0/Nodegroup", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1} to the global VBC
15:54:22.036 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/Nodegroup/0/Nodegroup", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. COMPLETED
15:54:22.058 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.PrimaryIndexOperationTracker - Primary index on dataset 8 and partition 0 is empty... skipping flush
15:54:22.101 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/DatasourceAdapter/0/DatasourceAdapter", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. STARTED
15:54:22.101 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the disk components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/DatasourceAdapter/0/DatasourceAdapter", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:22.102 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deallocating memory components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/DatasourceAdapter/0/DatasourceAdapter", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:22.115 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Unregistered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/DatasourceAdapter/0/DatasourceAdapter", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1} to the global VBC
15:54:22.127 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/DatasourceAdapter/0/DatasourceAdapter", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. COMPLETED
15:54:22.149 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.PrimaryIndexOperationTracker - Primary index on dataset 12 and partition 0 is empty... skipping flush
15:54:22.199 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/FeedPolicy/0/FeedPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. STARTED
15:54:22.200 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the disk components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/FeedPolicy/0/FeedPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:22.201 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deallocating memory components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/FeedPolicy/0/FeedPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:22.214 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Unregistered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/FeedPolicy/0/FeedPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1} to the global VBC
15:54:22.226 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/FeedPolicy/0/FeedPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. COMPLETED
15:54:22.279 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.PrimaryIndexOperationTracker - Primary index on dataset 13 and partition 0 is empty... skipping flush
15:54:22.382 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/CompactionPolicy/0/CompactionPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. STARTED
15:54:22.383 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the disk components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/CompactionPolicy/0/CompactionPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:22.384 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deallocating memory components of: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/CompactionPolicy/0/CompactionPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"[1,1]"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}
15:54:22.398 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.common.context.GlobalVirtualBufferCache - Unregistered metadata index {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/CompactionPolicy/0/CompactionPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1} to the global VBC
15:54:22.410 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.storage.am.lsm.common.impls.AbstractLSMIndex - Deactivating the index: {"class" : "LSMBTree", "dir" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/red/storage/partition_0/Metadata/CompactionPolicy/0/CompactionPolicy", "memory" : [{"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}, {"class":"LSMBTreeMemoryComponent", "state":"INACTIVE", "writers":0, "readers":0, "pendingFlushes":0, "id":"null"}], "disk" : 1, "num-scheduled-flushes":0, "current-memory-component":1}. COMPLETED
15:54:22.411 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Stopping component instance org.apache.asterix.app.nc.RecoveryManager; dump state: false, dump path: null
15:54:22.411 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Stopping component instance org.apache.asterix.transaction.management.service.logging.LogManager; dump state: false, dump path: null
15:54:22.411 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.transaction.management.service.logging.LogManager - Terminating LogFlusher thread ...
15:54:22.411 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.transaction.management.service.logging.LogManager - LogFlusher thread is terminated.
15:54:22.411 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.transaction.management.service.logging.LogManager - closing current log file with id(1)
15:54:22.412 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Stopping component instance org.apache.hyracks.storage.common.buffercache.BufferCache; dump state: false, dump path: null
15:54:22.413 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Stopping component instance org.apache.asterix.common.context.GlobalVirtualBufferCache; dump state: false, dump path: null
15:54:22.422 [asterix_nc1-Heartbeat] INFO org.apache.hyracks.control.nc.heartbeat.HeartbeatTask - Heartbeat task interrupted; shutting down
15:54:22.426 [IoRequestHandler-0] INFO org.apache.hyracks.control.nc.io.IoRequestHandler - Exiting
15:54:22.427 [IoRequestHandler-1] INFO org.apache.hyracks.control.nc.io.IoRequestHandler - Exiting
15:54:22.427 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.control.nc.NodeControllerService - Stopped NodeControllerService
16:38:44.724 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Setting uncaught exception handler org.apache.hyracks.api.lifecycle.LifeCycleComponentManager@15bbf42f
16:38:44.927 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Starting NodeControllerService
16:38:45.292 [main] INFO org.apache.hyracks.util.trace.Tracer - Initialize Tracer org.apache.hyracks.util.trace.Tracer.Traces.asterix_nc1
16:38:45.337 [main] INFO org.apache.hyracks.util.trace.Tracer - Set categories for Tracer org.apache.hyracks.util.trace.Tracer.Traces.asterix_nc1 to []
16:38:45.338 [main] INFO org.apache.hyracks.util.LoggingConfigUtil - Setting org.apache.hyracks log level to INFO
16:38:45.340 [main] INFO org.apache.hyracks.util.LoggingConfigUtil - Setting org.apache.asterix log level to INFO
16:38:45.580 [main] INFO org.apache.asterix.hyracks.bootstrap.ApplicationConfigurator - Found JRE version 1.8.0_131
16:38:46.759 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Starting Asterix node controller: asterix_nc1
16:38:47.731 [main] INFO org.apache.asterix.app.nc.TransactionSubsystem - Checkpoint Properties: {"class" : "CheckpointProperties", "checkpoint-dir-path" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog", "lsn-threshold" : 67108864, "poll-frequency" : 120, "history-to-keep" : 2, "dataset-checkpoint-interval" : 3600}
16:38:47.735 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Checkpoint directory = /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog
16:38:47.735 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:38:47.745 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:38:47.745 [main] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:38:48.276 [main] INFO org.apache.asterix.transaction.management.service.logging.LogManager - initializing log anchor with log file Id: 1 at offset: 0
16:38:48.276 [main] INFO org.apache.asterix.transaction.management.service.logging.LogManager - LogManager starts logging in LSN: 268435456
16:38:48.302 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:38:48.302 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:38:48.302 [main] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:38:48.304 [main] INFO org.apache.asterix.app.nc.NCAppRuntimeContext - The value of maxConcurrentFlushes is not provided. Setting maxConcurrentFlushes = 1.
16:38:48.759 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:38:48.759 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:38:48.759 [main] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:38:48.760 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:38:48.760 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:38:48.760 [main] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:38:48.760 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - System state: HEALTHY
16:38:48.760 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Node ID: asterix_nc1
16:38:48.761 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Stores: {asterix_nc1=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc3=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc2=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc5=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc4=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc7=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc6=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc9=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc8=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc12=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc11=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc10=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage]}
16:38:49.239 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - addCc: ec-hn/172.21.0.1:1099
16:38:49.352 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Registering with Cluster Controller ClusterControllerRemoteProxy [ec-hn/172.21.0.1:1099]
16:38:49.648 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Registering with Cluster Controller ClusterControllerRemoteProxy [ec-hn/172.21.0.1:1099] completed
16:38:49.683 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Started NodeControllerService
16:38:49.683 [Worker:asterix_nc1] INFO org.apache.hyracks.control.nc.work.AbortAllJobsWork - Aborting all tasks for controller CC:0
16:38:49.684 [main] INFO org.apache.hyracks.util.ExitUtil - successfully registered shutdown hook Thread[ShutdownHook-asterix_nc1,5,main]
16:38:49.809 [Executor-6:asterix_nc1] INFO org.apache.hyracks.control.nc.work.EnsureAllCcTasksCompleted - Ensuring all tasks of CC CC:0 have completed
16:38:49.984 [Executor-6:asterix_nc1] INFO org.apache.hyracks.control.nc.work.EnsureAllCcTasksCompleted - all tasks of CC CC:0 have completed
16:38:50.467 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:38:50.467 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:38:50.468 [Executor-6:asterix_nc1] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:38:50.498 [Worker:asterix_nc1] INFO org.apache.asterix.messaging.NCMessageBroker - Received message: org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage@1d0af4a8
16:38:50.499 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "UpdateNodeStatusTask" }
16:38:50.499 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Completed startup task: { "class" : "UpdateNodeStatusTask" }
16:38:50.499 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "MetadataBootstrapTask" }
16:38:50.500 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:38:50.500 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:38:50.500 [Executor-6:asterix_nc1] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:38:50.501 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.nc.NCAppRuntimeContext - Bootstrapping metadata
16:38:50.695 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.CachingTxnIdFactory - block exhausted; obtaining new block from supplier
16:38:50.715 [Worker:asterix_nc1] INFO org.apache.asterix.messaging.NCMessageBroker - Received message: TxnIdBlockResponse
16:38:50.822 [Executor-6:asterix_nc1] ERROR org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Failed during startup task
org.apache.hyracks.api.exceptions.HyracksDataException: attempt to create metadata index Dataverse. Index should already exist
at org.apache.hyracks.api.exceptions.HyracksDataException.create(HyracksDataException.java:51) ~[hyracks-api-0.3.6.jar:0.3.6]
at org.apache.asterix.app.nc.task.MetadataBootstrapTask.perform(MetadataBootstrapTask.java:45) ~[asterix-app-0.9.6.jar:0.9.6]
at org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage.handle(RegistrationTasksResponseMessage.java:63) ~[asterix-app-0.9.6.jar:0.9.6]
at org.apache.asterix.messaging.NCMessageBroker.lambda$receivedMessage$0(NCMessageBroker.java:98) ~[asterix-app-0.9.6.jar:0.9.6]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_131]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_131]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_131]
Caused by: org.apache.asterix.common.exceptions.MetadataException: attempt to create metadata index Dataverse. Index should already exist
at org.apache.asterix.metadata.bootstrap.MetadataBootstrap.startUniverse(MetadataBootstrap.java:190) ~[asterix-metadata-0.9.6.jar:0.9.6]
at org.apache.asterix.app.nc.NCAppRuntimeContext.initializeMetadata(NCAppRuntimeContext.java:451) ~[asterix-app-0.9.6.jar:0.9.6]
at org.apache.asterix.app.nc.task.MetadataBootstrapTask.perform(MetadataBootstrapTask.java:43) ~[asterix-app-0.9.6.jar:0.9.6]
... 7 more
Caused by: java.lang.IllegalStateException: attempt to create metadata index Dataverse. Index should already exist
at org.apache.asterix.metadata.bootstrap.MetadataBootstrap.ensureCatalogUpgradability(MetadataBootstrap.java:515) ~[asterix-metadata-0.9.6.jar:0.9.6]
at org.apache.asterix.metadata.bootstrap.MetadataBootstrap.enlistMetadataDataset(MetadataBootstrap.java:382) ~[asterix-metadata-0.9.6.jar:0.9.6]
at org.apache.asterix.metadata.bootstrap.MetadataBootstrap.startUniverse(MetadataBootstrap.java:154) ~[asterix-metadata-0.9.6.jar:0.9.6]
at org.apache.asterix.app.nc.NCAppRuntimeContext.initializeMetadata(NCAppRuntimeContext.java:451) ~[asterix-app-0.9.6.jar:0.9.6]
at org.apache.asterix.app.nc.task.MetadataBootstrapTask.perform(MetadataBootstrapTask.java:43) ~[asterix-app-0.9.6.jar:0.9.6]
... 7 more
16:38:50.909 [ShutdownWatchdog] INFO org.apache.hyracks.util.ExitUtil - starting shutdown watchdog- system will halt if shutdown is not completed within 600 seconds
16:38:50.909 [JVM exit thread] WARN org.apache.hyracks.util.ExitUtil - JVM exiting with status 2; bye!
java.lang.Throwable: exit callstack
at org.apache.hyracks.util.ExitUtil.exit(ExitUtil.java:89) ~[hyracks-util-0.3.6.jar:0.3.6]
at org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage.handle(RegistrationTasksResponseMessage.java:86) ~[asterix-app-0.9.6.jar:0.9.6]
at org.apache.asterix.messaging.NCMessageBroker.lambda$receivedMessage$0(NCMessageBroker.java:98) ~[asterix-app-0.9.6.jar:0.9.6]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_131]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_131]
at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_131]
16:38:50.912 [JVM exit thread] INFO org.apache.hyracks.util.ExitUtil - the following (2) shutdown hooks have been registered: {Thread[ShutdownHook-asterix_nc1,5,main]=Thread[ShutdownHook-asterix_nc1,5,main], Thread[Thread-0,5,main]=Thread[Thread-0,5,main]}
16:38:50.936 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.control.common.ControllerShutdownHook - Shutdown hook called
16:38:50.937 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.control.nc.NodeControllerService - Stopping NodeControllerService
16:38:50.953 [ShutdownHook-asterix_nc1] WARN org.apache.asterix.active.ActiveManager - Shutting down ActiveManager on node asterix_nc1
16:38:50.979 [ShutdownHook-asterix_nc1] WARN org.apache.asterix.active.ActiveManager - Shutdown ActiveManager on node asterix_nc1 complete
16:38:50.980 [Executor-5:asterix_nc1] WARN org.apache.hyracks.control.nc.result.ResultPartitionManager - Result cleaner thread interrupted, shutting down.
16:38:50.981 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Stopping Asterix node controller: asterix_nc1
16:38:53.273 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Attempting to stop org.apache.hyracks.api.lifecycle.LifeCycleComponentManager@15bbf42f
16:38:53.274 [ShutdownHook-asterix_nc1] ERROR org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Lifecycle management not configured org.apache.hyracks.api.lifecycle.LifeCycleComponentManager@15bbf42f
16:38:53.276 [asterix_nc1-Heartbeat] INFO org.apache.hyracks.control.nc.heartbeat.HeartbeatTask - Heartbeat task interrupted; shutting down
16:38:53.323 [IoRequestHandler-0] INFO org.apache.hyracks.control.nc.io.IoRequestHandler - Exiting
16:38:53.324 [IoRequestHandler-1] INFO org.apache.hyracks.control.nc.io.IoRequestHandler - Exiting
16:38:53.324 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.control.nc.NodeControllerService - Stopped NodeControllerService
16:57:01.390 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Setting uncaught exception handler org.apache.hyracks.api.lifecycle.LifeCycleComponentManager@15bbf42f
16:57:01.501 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Starting NodeControllerService
16:57:01.755 [main] INFO org.apache.hyracks.util.trace.Tracer - Initialize Tracer org.apache.hyracks.util.trace.Tracer.Traces.asterix_nc1
16:57:01.784 [main] INFO org.apache.hyracks.util.trace.Tracer - Set categories for Tracer org.apache.hyracks.util.trace.Tracer.Traces.asterix_nc1 to []
16:57:01.785 [main] INFO org.apache.hyracks.util.LoggingConfigUtil - Setting org.apache.hyracks log level to INFO
16:57:01.787 [main] INFO org.apache.hyracks.util.LoggingConfigUtil - Setting org.apache.asterix log level to INFO
16:57:01.792 [main] INFO org.apache.asterix.hyracks.bootstrap.ApplicationConfigurator - Found JRE version 1.8.0_131
16:57:02.501 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Starting Asterix node controller: asterix_nc1
16:57:03.045 [main] INFO org.apache.asterix.app.nc.TransactionSubsystem - Checkpoint Properties: {"class" : "CheckpointProperties", "checkpoint-dir-path" : "/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog", "lsn-threshold" : 67108864, "poll-frequency" : 120, "history-to-keep" : 2, "dataset-checkpoint-interval" : 3600}
16:57:03.049 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Checkpoint directory = /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog
16:57:03.049 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:57:03.049 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:57:03.050 [main] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:57:03.405 [main] INFO org.apache.asterix.transaction.management.service.logging.LogManager - initializing log anchor with log file Id: 1 at offset: 0
16:57:03.405 [main] INFO org.apache.asterix.transaction.management.service.logging.LogManager - LogManager starts logging in LSN: 268435456
16:57:03.418 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:57:03.418 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:57:03.418 [main] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:57:03.420 [main] INFO org.apache.asterix.app.nc.NCAppRuntimeContext - The value of maxConcurrentFlushes is not provided. Setting maxConcurrentFlushes = 1.
16:57:03.654 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:57:03.654 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:57:03.654 [main] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:57:03.655 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:57:03.655 [main] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:57:03.655 [main] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:57:03.656 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - System state: HEALTHY
16:57:03.656 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Node ID: asterix_nc1
16:57:03.656 [main] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Stores: {asterix_nc1=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc3=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc2=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc5=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc4=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc7=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc6=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc9=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc8=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc12=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc11=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage], asterix_nc10=[/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/storage]}
16:57:04.069 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - addCc: ec-hn/172.21.0.1:1099
16:57:04.148 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Registering with Cluster Controller ClusterControllerRemoteProxy [ec-hn/172.21.0.1:1099]
16:57:04.398 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Registering with Cluster Controller ClusterControllerRemoteProxy [ec-hn/172.21.0.1:1099] completed
16:57:04.433 [main] INFO org.apache.hyracks.control.nc.NodeControllerService - Started NodeControllerService
16:57:04.433 [main] INFO org.apache.hyracks.util.ExitUtil - successfully registered shutdown hook Thread[ShutdownHook-asterix_nc1,5,main]
16:57:04.433 [Worker:asterix_nc1] INFO org.apache.hyracks.control.nc.work.AbortAllJobsWork - Aborting all tasks for controller CC:0
16:57:04.459 [Executor-6:asterix_nc1] INFO org.apache.hyracks.control.nc.work.EnsureAllCcTasksCompleted - Ensuring all tasks of CC CC:0 have completed
16:57:04.481 [Executor-6:asterix_nc1] INFO org.apache.hyracks.control.nc.work.EnsureAllCcTasksCompleted - all tasks of CC CC:0 have completed
16:57:04.845 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:57:04.845 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:57:04.845 [Executor-6:asterix_nc1] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:57:04.877 [Worker:asterix_nc1] INFO org.apache.asterix.messaging.NCMessageBroker - Received message: org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage@48a71e51
16:57:04.878 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "UpdateNodeStatusTask" }
16:57:04.878 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Completed startup task: { "class" : "UpdateNodeStatusTask" }
16:57:04.878 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Starting startup task: { "class" : "MetadataBootstrapTask" }
16:57:04.879 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Getting latest checkpoint
16:57:04.879 [Executor-6:asterix_nc1] INFO org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Listing of files in the checkpoint dir returned [/local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0]
16:57:04.879 [Executor-6:asterix_nc1] WARN org.apache.asterix.transaction.management.service.recovery.AbstractCheckpointManager - Reading checkpoint file: /local_data/dblab/pkgs/apache-asterixdb-0.9.6/opt/local/data/blue/txnlog/checkpoint_0
16:57:04.880 [Executor-6:asterix_nc1] INFO org.apache.asterix.app.nc.NCAppRuntimeContext - Bootstrapping metadata
16:57:04.982 [Executor-6:asterix_nc1] INFO org.apache.asterix.metadata.CachingTxnIdFactory - block exhausted; obtaining new block from supplier
16:57:04.992 [Worker:asterix_nc1] INFO org.apache.asterix.messaging.NCMessageBroker - Received message: TxnIdBlockResponse
16:57:05.041 [Executor-6:asterix_nc1] ERROR org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage - Failed during startup task
org.apache.hyracks.api.exceptions.HyracksDataException: attempt to create metadata index Dataverse. Index should already exist
at org.apache.hyracks.api.exceptions.HyracksDataException.create(HyracksDataException.java:51) ~[hyracks-api-0.3.6.jar:0.3.6]
at org.apache.asterix.app.nc.task.MetadataBootstrapTask.perform(MetadataBootstrapTask.java:45) ~[asterix-app-0.9.6.jar:0.9.6]
at org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage.handle(RegistrationTasksResponseMessage.java:63) ~[asterix-app-0.9.6.jar:0.9.6]
at org.apache.asterix.messaging.NCMessageBroker.lambda$receivedMessage$0(NCMessageBroker.java:98) ~[asterix-app-0.9.6.jar:0.9.6]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_131]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_131]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_131]
Caused by: org.apache.asterix.common.exceptions.MetadataException: attempt to create metadata index Dataverse. Index should already exist
at org.apache.asterix.metadata.bootstrap.MetadataBootstrap.startUniverse(MetadataBootstrap.java:190) ~[asterix-metadata-0.9.6.jar:0.9.6]
at org.apache.asterix.app.nc.NCAppRuntimeContext.initializeMetadata(NCAppRuntimeContext.java:451) ~[asterix-app-0.9.6.jar:0.9.6]
at org.apache.asterix.app.nc.task.MetadataBootstrapTask.perform(MetadataBootstrapTask.java:43) ~[asterix-app-0.9.6.jar:0.9.6]
... 7 more
Caused by: java.lang.IllegalStateException: attempt to create metadata index Dataverse. Index should already exist
at org.apache.asterix.metadata.bootstrap.MetadataBootstrap.ensureCatalogUpgradability(MetadataBootstrap.java:515) ~[asterix-metadata-0.9.6.jar:0.9.6]
at org.apache.asterix.metadata.bootstrap.MetadataBootstrap.enlistMetadataDataset(MetadataBootstrap.java:382) ~[asterix-metadata-0.9.6.jar:0.9.6]
at org.apache.asterix.metadata.bootstrap.MetadataBootstrap.startUniverse(MetadataBootstrap.java:154) ~[asterix-metadata-0.9.6.jar:0.9.6]
at org.apache.asterix.app.nc.NCAppRuntimeContext.initializeMetadata(NCAppRuntimeContext.java:451) ~[asterix-app-0.9.6.jar:0.9.6]
at org.apache.asterix.app.nc.task.MetadataBootstrapTask.perform(MetadataBootstrapTask.java:43) ~[asterix-app-0.9.6.jar:0.9.6]
... 7 more
16:57:05.102 [ShutdownWatchdog] INFO org.apache.hyracks.util.ExitUtil - starting shutdown watchdog- system will halt if shutdown is not completed within 600 seconds
16:57:05.103 [JVM exit thread] WARN org.apache.hyracks.util.ExitUtil - JVM exiting with status 2; bye!
java.lang.Throwable: exit callstack
at org.apache.hyracks.util.ExitUtil.exit(ExitUtil.java:89) ~[hyracks-util-0.3.6.jar:0.3.6]
at org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage.handle(RegistrationTasksResponseMessage.java:86) ~[asterix-app-0.9.6.jar:0.9.6]
at org.apache.asterix.messaging.NCMessageBroker.lambda$receivedMessage$0(NCMessageBroker.java:98) ~[asterix-app-0.9.6.jar:0.9.6]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_131]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_131]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_131]
at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_131]
16:57:05.105 [JVM exit thread] INFO org.apache.hyracks.util.ExitUtil - the following (2) shutdown hooks have been registered: {Thread[ShutdownHook-asterix_nc1,5,main]=Thread[ShutdownHook-asterix_nc1,5,main], Thread[Thread-0,5,main]=Thread[Thread-0,5,main]}
16:57:05.120 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.control.common.ControllerShutdownHook - Shutdown hook called
16:57:05.121 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.control.nc.NodeControllerService - Stopping NodeControllerService
16:57:05.147 [ShutdownHook-asterix_nc1] WARN org.apache.asterix.active.ActiveManager - Shutting down ActiveManager on node asterix_nc1
16:57:05.178 [ShutdownHook-asterix_nc1] WARN org.apache.asterix.active.ActiveManager - Shutdown ActiveManager on node asterix_nc1 complete
16:57:05.179 [Executor-5:asterix_nc1] WARN org.apache.hyracks.control.nc.result.ResultPartitionManager - Result cleaner thread interrupted, shutting down.
16:57:05.180 [ShutdownHook-asterix_nc1] INFO org.apache.asterix.hyracks.bootstrap.NCApplication - Stopping Asterix node controller: asterix_nc1
16:57:07.531 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Attempting to stop org.apache.hyracks.api.lifecycle.LifeCycleComponentManager@15bbf42f
16:57:07.531 [ShutdownHook-asterix_nc1] ERROR org.apache.hyracks.api.lifecycle.LifeCycleComponentManager - Lifecycle management not configured org.apache.hyracks.api.lifecycle.LifeCycleComponentManager@15bbf42f
16:57:07.535 [asterix_nc1-Heartbeat] INFO org.apache.hyracks.control.nc.heartbeat.HeartbeatTask - Heartbeat task interrupted; shutting down
16:57:07.539 [IoRequestHandler-0] INFO org.apache.hyracks.control.nc.io.IoRequestHandler - Exiting
16:57:07.540 [IoRequestHandler-1] INFO org.apache.hyracks.control.nc.io.IoRequestHandler - Exiting
16:57:07.540 [ShutdownHook-asterix_nc1] INFO org.apache.hyracks.control.nc.NodeControllerService - Stopped NodeControllerService
