Hello,
The title says it all. I just upgraded from a nicely working 5.0.1 to 5.1.1 on my Mac. After reboot, I am unable to create indexes. The cbq command returns now:
Connected to : http://localhost:8091/. Type Ctrl-D or \QUIT to exit.
Path to history file for the shell : /Users/myuser/.cbq_history
create primary index on hx2a
{
“requestID”: “65b129aa-bc78-4205-abce-702877dab27a”,
“signature”: null,
“results”: [
],
“errors”: [
{
“code”: 12005,
“msg”: “Indexer not implemented GSI may not be enabled”
}
],
“status”: “errors”,
“metrics”: {
“elapsedTime”: “2.938ms”,
“executionTime”: “2.908ms”,
“resultCount”: 0,
“resultSize”: 0,
“errorCount”: 1
}
}
I’ve upgraded my Couchbase version many times on my machine the last years, and never faced something like this. Maybe 5.1.1 was not able to read properly the former server configuration? Is there some parameter somewhere to activate GSI?
Thanks!
@Hawkeye, can you check if indexer process is running? Please check the indexer.log for any errors or you can share it here.
What is the name of the process?
Here is the indexer.log:
2018-06-06T15:17:57.008-04:00 [Info] Indexer started with command line: [/Applications/Couchbase Server.app/Contents/Resources/couchbase-core/bin/indexer -vbuckets=64 -cluster=127.0.0.1:8091 -adminPort=9100 -scanPort=9101 -httpPort=9102 -streamInitPort=9103 -streamCatchupPort=9104 -streamMaintPort=9105 -storageDir=/Users/myuser/Library/Application Support/Couchbase/var/lib/couchbase/data/@2i -diagDir=/Users/myuser/Library/Application Support/Couchbase/var/lib/couchbase/crash -nodeUUID=8542b375caba126f395adc088ec273d3 -isEnterprise=false -storageMode=forestdb]
2018-06-06T15:17:57.008-04:00 [Info] Indexer::Cluster Storage Mode Set forestdb
2018-06-06T15:17:57.022-04:00 [Info] Indexer::NewIndexer Status Warmup
2018-06-06T15:18:00.024-04:00 [Info] Setting buffer block size to 16384 bytes
2018-06-06T15:18:00.024-04:00 [Info] Setting maxcpus = 8
2018-06-06T15:18:00.024-04:00 [Info] Setting log level to Info
2018-06-06T15:18:00.024-04:00 [Info] Indexer::NewIndexer Starting with Vbuckets 64
2018-06-06T15:18:00.024-04:00 [Info] Indexer::NewIndexer Build Mode Set Community
2018-06-06T15:18:00.040-04:00 [Info] New settings received:
{“indexer.settings.compaction.days_of_week”:“Sunday,Monday,Tuesday,Wednesday,Thursday,Friday,Saturday”,“indexer.settings.compaction.interval”:“00:00,00:00”,“indexer.settings.log_level”:“info”,“indexer.settings.persisted_snapshot.interval”:5000,“indexer.settings.compaction.compaction_mode”:“circular”,“indexer.settings.compaction.min_frag”:30,“indexer.settings.inmemory_snapshot.interval”:200,“indexer.settings.max_cpu_percent”:0,“indexer.settings.storage_mode”:“forestdb”,“indexer.settings.recovery.max_rollbacks”:5,“indexer.settings.memory_quota”:536870912,“indexer.settings.compaction.abort_exceed_interval”:false}
2018-06-06T15:18:00.041-04:00 [Info] Setting maxcpus = 8
2018-06-06T15:18:00.041-04:00 [Info] Setting log level to Info
2018-06-06T15:18:00.043-04:00 [Info] [Queryport “:9101”] started …
2018-06-06T15:18:00.062-04:00 [Info] Unable to fetch storage mode from metakv during bootrap. Use storage mode setting for bootstrap
2018-06-06T15:18:00.071-04:00 [Info] bootstrap storage mode forestdb
2018-06-06T15:18:00.123-04:00 [Info] servicesChangeNotifier: Creating new notifier instance for http://%40index-cbauth@127.0.0.1:8091, default
2018-06-06T15:18:00.124-04:00 [Info] serviceChangeNotifier: received ServiceChangeNotification
2018-06-06T15:18:00.125-04:00 [Info] serviceChangeNotifier: received PoolChangeNotification
2018-06-06T15:18:00.132-04:00 [INFO][FDB] Forestdb blockcache size 348962816 initialized in 8859 us
2018-06-06T15:18:00.132-04:00 [INFO][FDB] Forestdb opened database file /Users/myuser/Library/Application Support/Couchbase/var/lib/couchbase/data/@2i/MetadataStore
2018-06-06T15:18:00.465-04:00 [Info] Indexer::indexer version 2
2018-06-06T15:18:00.465-04:00 [Info] ClustMgr:handleGetLocalValue Key IndexerId
2018-06-06T15:18:00.466-04:00 [Info] Indexer Id 8542b375caba126f395adc088ec273d3
2018-06-06T15:18:00.477-04:00 [Info] KVSender::sendShutdownTopic Projector 127.0.0.1:9999 Topic MAINT_STREAM_TOPIC_8542b375caba126f395adc088ec273d3
2018-06-06T15:18:00.478-04:00 [Error] KVSender::sendShutdownTopic Unexpected Error During Shutdown Projector 127.0.0.1:9999 Topic MAINT_STREAM_TOPIC_8542b375caba126f395adc088ec273d3. Err projector.topicMissing
2018-06-06T15:18:00.478-04:00 [Error] KVSender::closeMutationStream MAINT_STREAM Error Received projector.topicMissing from 127.0.0.1:9999
2018-06-06T15:18:00.478-04:00 [Info] KVSender::closeMutationStream MAINT_STREAM Treating projector.topicMissing As Success
2018-06-06T15:18:00.487-04:00 [Info] KVSender::sendShutdownTopic Projector 127.0.0.1:9999 Topic INIT_STREAM_TOPIC_8542b375caba126f395adc088ec273d3
2018-06-06T15:18:00.488-04:00 [Error] KVSender::sendShutdownTopic Unexpected Error During Shutdown Projector 127.0.0.1:9999 Topic INIT_STREAM_TOPIC_8542b375caba126f395adc088ec273d3. Err projector.topicMissing
2018-06-06T15:18:00.488-04:00 [Error] KVSender::closeMutationStream INIT_STREAM Error Received projector.topicMissing from 127.0.0.1:9999
2018-06-06T15:18:00.488-04:00 [Info] KVSender::closeMutationStream INIT_STREAM Treating projector.topicMissing As Success
2018-06-06T15:18:00.488-04:00 [Info] ClustMgr:handleGetLocalValue Key RebalanceRunning
2018-06-06T15:18:00.488-04:00 [Info] ClustMgr:handleGetLocalValue Key RebalanceToken
2018-06-06T15:18:00.488-04:00 [Info] Indexer::recoverRebalanceState RebalanceRunning false RebalanceToken
2018-06-06T15:18:00.488-04:00 [Info] ClustMgr:handleGetGlobalTopology &{map[]}
2018-06-06T15:18:00.488-04:00 [Info] Indexer::initFromPersistedState Recovered IndexInstMap
2018-06-06T15:18:00.489-04:00 [Info] Indexer::local storage mode forestdb
2018-06-06T15:18:00.489-04:00 [Info] MutationMgr::handleUpdateIndexInstMap
Message: MsgUpdateInstMap
2018-06-06T15:18:00.489-04:00 [Info] MutationMgr::handleUpdateIndexPartnMap
Message: MsgUpdatePartnMap
2018-06-06T15:18:00.489-04:00 [Info] ClustMgr:handleIndexMap
Message: MsgUpdateInstMap
2018-06-06T15:18:00.489-04:00 [Info] ClustMgr:handleIndexerReady &{54 [] {false false false false false} 0 false }
2018-06-06T15:18:00.489-04:00 [Info] janitor: running cleanup.
2018-06-06T15:18:00.489-04:00 [Info] builder: recovering scheduled index
2018-06-06T15:18:00.490-04:00 [Info] Indexer::updateStorageMode Try setting storage mode to forestdb
2018-06-06T15:18:00.490-04:00 [Info] DDLServiceMgr: intialized. Local nodeUUID 8542b375caba126f395adc088ec273d3
2018-06-06T15:18:00.490-04:00 [Info] RebalanceMgr::NewRebalanceMgr false
2018-06-06T15:18:00.490-04:00 [Info] ClustMgr:handleSetLocalValue Key IndexerNodeUUID Value 8542b375caba126f395adc088ec273d3
2018-06-06T15:18:00.490-04:00 [Info] Indexer::NewIndexer Status Active
2018-06-06T15:18:00.490-04:00 [Info] 127.0.0.1:8091 starting RESTful services
2018-06-06T15:18:00.491-04:00 [Info] janitor: Processing delete token /indexing/ddl/commandToken/delete/13846975424310443467
2018-06-06T15:18:00.491-04:00 [Info] janitor: Processing delete token /indexing/ddl/commandToken/delete/14751130100210538190
2018-06-06T15:18:00.491-04:00 [Info] janitor: Processing delete token /indexing/ddl/commandToken/delete/678043815319772933
2018-06-06T15:18:00.491-04:00 [Info] janitor: Processing delete token /indexing/ddl/commandToken/delete/840903983808820902
2018-06-06T15:18:00.491-04:00 [Info] janitor: Processing delete token /indexing/ddl/commandToken/delete/9583451000413437244
2018-06-06T15:18:00.491-04:00 [Info] RebalanceMgr::initService Init
2018-06-06T15:18:00.492-04:00 [Info] ServiceMgr::registerWithServer nodeuuid 8542b375caba126f395adc088ec273d3
2018-06-06T15:18:00.491-04:00 [Info] ServiceMgr::listenMoveIndex &{8542b375caba126f395adc088ec273d3 2 }
2018-06-06T15:18:00.492-04:00 [Info] Indexer::monitorMemUsage started…
2018-06-06T15:18:00.492-04:00 [Info] progress stats collection done.
2018-06-06T15:18:00.492-04:00 [Info] send progress stats to clients
2018-06-06T15:18:00.492-04:00 [Info] ClustMgr:handleStats &{93 false}
2018-06-06T15:18:00.492-04:00 [Info] Indexer::ReadMemstats Time Taken 63µs
2018-06-06T15:18:00.492-04:00 [Info] memstats {“Alloc”:0, “TotalAlloc”:0, “Sys”:0, “Lookups”:0, “Mallocs”:0,“Frees”:0, “HeapAlloc”:0, “HeapSys”:0, “HeapIdle”:0, “HeapInuse”:0,“HeapReleased”:0, “HeapObjects”:0,“GCSys”:0, “LastGC”:0,“PauseTotalNs”:0, “PauseNs”:[], “NumGC”:0}
2018-06-06T15:18:00.493-04:00 [Info] ServiceMgr::GetTaskList []
2018-06-06T15:18:00.493-04:00 [Info] ServiceMgr::GetTaskList returns &{[0 0 0 0 0 0 0 0] []}
2018-06-06T15:18:00.494-04:00 [Info] Indexer::updateStorageMode Try setting storage mode to forestdb
2018-06-06T15:18:00.494-04:00 [Info] Indexer: Setting GC percent to 100
2018-06-06T15:18:00.504-04:00 [Info] CompactionManager: Refreshing settings
2018-06-06T15:18:00.504-04:00 [Info] MutationMgr::MaxQueueMemoryQuota 107374182
2018-06-06T15:18:00.504-04:00 [Info] ClustMgr:handleConfigUpdate
2018-06-06T15:18:00.504-04:00 [Info] ServiceMgr::GetCurrentTopology []
2018-06-06T15:18:00.504-04:00 [Info] ServiceMgr::GetCurrentTopology returns &{[0 0 0 0 0 0 0 0] [8542b375caba126f395adc088ec273d3] true []}
2018-06-06T15:18:00.505-04:00 [Info] ServiceMgr::GetTaskList [0 0 0 0 0 0 0 0]
2018-06-06T15:18:00.505-04:00 [Info] ServiceMgr::GetCurrentTopology [0 0 0 0 0 0 0 0]
2018-06-06T15:18:00.549-04:00 [Info] updator: updating service map. server group=Group 1, indexerVersion=2 nodeAddr 127.0.0.1:8091 clusterVersion 2
2018-06-06T15:18:00.552-04:00 [Error] ServiceMgr::updateNodeList Updated Node List [8542b375caba126f395adc088ec273d3]
2018-06-06T15:18:00.552-04:00 [Info] ServiceMgr::GetTaskList returns &{[0 0 0 0 0 0 0 1] []}
2018-06-06T15:18:00.552-04:00 [Info] ServiceMgr::GetCurrentTopology returns &{[0 0 0 0 0 0 0 1] [8542b375caba126f395adc088ec273d3] true []}
2018-06-06T15:18:00.553-04:00 [Info] ServiceMgr::GetTaskList [0 0 0 0 0 0 0 1]
2018-06-06T15:18:00.553-04:00 [Info] ServiceMgr::GetCurrentTopology [0 0 0 0 0 0 0 1]
2018-06-06T15:18:01.228-04:00 [Info] ClustMgr:handleStats &{93 false}
2018-06-06T15:18:01.812-04:00 [Info] serviceChangeNotifier: received PoolChangeNotification
2018-06-06T15:18:06.228-04:00 [Info] ClustMgr:handleStats &{93 false}
2018-06-06T15:18:10.492-04:00 [Info] Indexer::ReadMemstats Time Taken 46µs
2018-06-06T15:18:11.468-04:00 [Info] cpuCollector: cpu percent 1.3972055888223553 for pid 938
2018-06-06T15:18:12.230-04:00 [Info] ClustMgr:handleStats &{93 false}
indexer.log looks to be fine. The name of the process is indexer(of indexer.exe on windows). Please check the query.log as well.
The indexer process is running. I’ll have a look at the query.log (although I made no query whatsoever, just started the server and ran cbq to create a primary index).
I removed query.log to give you a completely “fresh” one, and restarted the server. Now it is accepting to create indexes.
One thing that I had done (besides upgrading the server), is to upload a document with duplicate keys. It might have confused the server to the point it could not properly start some of its services? That’s the only explanation I can find.
Looks like its the restart that alleviated the problem. query.log might have had some useful clues as to what was not working correctly before restart. I don’t think a document with duplicate keys can cause services to stall. There are some shared services (e.g. authentication). If those are not able to come up correctly, it could lead to above behavior.
I restarted several times, so it should not be the restart which made it work. The only thing I did before the last restart was to remove the query.log file.
Anyway, everything works now, I’ll be more specific the next time it happens.
Thanks.