Missing steps in Vagrant setup? about graylog2-images

[fhemberger]

And for fun, here is the entire log output I got after all those steps – I still don't know what the problem is, hopefully you can help me:

vagrant@graylog2:/opt/graylog2/server$ sudo -u graylog2 java -jar graylog2-server.jar
2015-01-03 08:47:24,962 DEBUG: org.graylog2.Main - Loading configuration from config file: /etc/graylog2.conf
2015-01-03 08:47:25,171 DEBUG: org.graylog2.Main - No rest_transport_uri set. Using default [http://127.0.0.1:12900/].
2015-01-03 08:47:26,120 INFO : org.reflections.Reflections - Reflections took 832 ms to scan 1 urls, producing 11 keys and 20 values
2015-01-03 08:47:26,679 INFO : org.reflections.Reflections - Reflections took 258 ms to scan 1 urls, producing 5 keys and 24 values
2015-01-03 08:47:31,083 INFO : org.graylog2.plugin.system.NodeId - Node ID: 609b093f-cc74-4340-8c84-4b9d8a4ca43e
2015-01-03 08:47:31,917 INFO : org.graylog2.caches.DiskJournalCache - Compacting off-heap message cache database files (input-cache)
2015-01-03 08:47:32,285 INFO : org.elasticsearch.node - [graylog2-server] version[1.3.4], pid[24303], build[a70f3cc/2014-09-30T09:07:17Z]
2015-01-03 08:47:32,286 INFO : org.elasticsearch.node - [graylog2-server] initializing ...
2015-01-03 08:47:32,293 INFO : org.elasticsearch.plugins - [graylog2-server] loaded [], sites []
2015-01-03 08:47:37,263 INFO : org.elasticsearch.node - [graylog2-server] initialized
2015-01-03 08:47:37,274 INFO : org.graylog2.caches.DiskJournalCache - Compacting off-heap message cache database files (output-cache)
2015-01-03 08:47:38,087 INFO : org.graylog2.buffers.OutputBuffer - Initialized OutputBuffer with ring size <1024> and wait strategy <BlockingWaitStrategy>.
2015-01-03 08:47:38,186 INFO : org.graylog2.Main - Graylog2 Server 0.92.3 (102a59f) starting up. (JRE: Oracle Corporation 1.7.0_65 on Linux 3.13.0-32-generic)
2015-01-03 08:47:38,317 INFO : org.graylog2.shared.initializers.PeriodicalsService - Starting 17 periodicals ...
2015-01-03 08:47:38,327 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.ThroughputCounterManagerThread] periodical in [0s], polling every [1s].
2015-01-03 08:47:38,336 INFO : org.elasticsearch.node - [graylog2-server] starting ...
2015-01-03 08:47:38,350 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.StreamThroughputCounterManagerThread] periodical in [0s], polling every [1s].
2015-01-03 08:47:38,409 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.DeadLetterThread] periodical, running forever.
2015-01-03 08:47:38,411 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.VersionCheckThread] periodical in [0s], polling every [1800s].
2015-01-03 08:47:38,426 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.AlertScannerThread] periodical in [10s], polling every [60s].
2015-01-03 08:47:38,427 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.BatchedElasticSearchOutputFlushThread] periodical in [0s], polling every [1s].
2015-01-03 08:47:38,429 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.ClusterHealthCheckThread] periodical in [0s], polling every [20s].
2015-01-03 08:47:38,430 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.GarbageCollectionWarningThread] periodical, running forever.
2015-01-03 08:47:38,463 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.ContentPackLoaderPeriodical] periodical, running forever.
2015-01-03 08:47:38,465 INFO : org.graylog2.shared.initializers.PeriodicalsService - Not starting [org.graylog2.periodical.TelemetryReporterThread] periodical. Not configured to run on this node.
2015-01-03 08:47:38,466 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.IndexerClusterCheckerThread] periodical in [0s], polling every [30s].
2015-01-03 08:47:38,469 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.IndexRotationThread] periodical in [0s], polling every [10s].
2015-01-03 08:47:38,471 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.NodePingThread] periodical in [0s], polling every [1s].
2015-01-03 08:47:38,547 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.OutputCacheWorkerThread] periodical, running forever.
2015-01-03 08:47:38,548 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.MasterCacheWorkerThread] periodical, running forever.
2015-01-03 08:47:38,550 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.InputCacheWorkerThread] periodical, running forever.
2015-01-03 08:47:38,555 INFO : org.graylog2.periodical.Periodicals - Starting [org.graylog2.periodical.IndexRetentionThread] periodical in [0s], polling every [300s].
2015-01-03 08:47:38,651 INFO : org.graylog2.periodical.IndexRetentionThread - Elasticsearch cluster not available, skipping index retention checks.
2015-01-03 08:47:38,666 INFO : org.graylog2.periodical.IndexerClusterCheckerThread - Indexer not fully initialized yet. Skipping periodic cluster check.
2015-01-03 08:47:39,387 INFO : org.reflections.Reflections - Reflections took 899 ms to scan 1 urls, producing 2 keys and 2 values
2015-01-03 08:47:39,696 INFO : org.elasticsearch.transport - [graylog2-server] bound_address {inet[/0:0:0:0:0:0:0:0:9350]}, publish_address {inet[/10.0.2.15:9350]}
2015-01-03 08:47:39,860 INFO : org.elasticsearch.discovery - [graylog2-server] graylog2/KQb_YPinQhSoZlb-rn7bsQ
2015-01-03 08:47:42,933 WARN : org.elasticsearch.discovery - [graylog2-server] waited for 3s and no initial state was set by the discovery
2015-01-03 08:47:42,934 INFO : org.elasticsearch.node - [graylog2-server] started
2015-01-03 08:47:46,553 INFO : org.drools.compiler.kie.builder.impl.KieRepositoryImpl - KieModule was added:MemoryKieModule[ ReleaseId=org.graylog2:dynamic-rules:0]
2015-01-03 08:47:46,690 INFO : org.drools.compiler.kie.builder.impl.KieRepositoryImpl - Adding KieModule from resource :[ByteArrayResource resource=[B@1e82d7dc]
2015-01-03 08:47:47,144 INFO : org.drools.compiler.kie.builder.impl.KieRepositoryImpl - KieModule was added:MemoryKieModule[ ReleaseId=org.graylog2:dynamic-rules:0]
2015-01-03 08:47:47,648 INFO : org.graylog2.bindings.providers.RulesEngineProvider - No static rules file loaded.
2015-01-03 08:47:47,949 INFO : org.graylog2.shared.buffers.ProcessBuffer - Initialized ProcessBuffer with ring size <1024> and wait strategy <BlockingWaitStrategy>.
2015-01-03 08:47:47,999 ERROR: org.graylog2.UI -

################################################################################

ERROR: Could not successfully connect to Elasticsearch. Check that your cluster state is not RED and that Elasticsearch is running properly.

Need help?

* Official documentation: http://graylog2.org/resources/documentation
* Community support: http://graylog2.org/resources/community-support
* Commercial support: http://graylog2.org/products

But we also got some specific help pages that might help you in this case:

* http://www.graylog2.org/resources/documentation/setup/elasticsearch

Terminating. :(

################################################################################

2015-01-03 08:47:48,022 ERROR: com.google.common.util.concurrent.ServiceManager - Service IndexerSetupService [FAILED] has failed in the STARTING state.
java.lang.IllegalStateException
    at org.graylog2.UI.exitHardWithWall(UI.java:39)
    at org.graylog2.initializers.IndexerSetupService.startUp(IndexerSetupService.java:149)
    at com.google.common.util.concurrent.AbstractIdleService$2$1.run(AbstractIdleService.java:54)
    at com.google.common.util.concurrent.Callables$3.run(Callables.java:95)
    at java.lang.Thread.run(Thread.java:745)
2015-01-03 08:47:48,079 ERROR: org.graylog2.shared.initializers.InputSetupService - Not starting any inputs because lifecycle is: Uninitialized [LB:DEAD]
2015-01-03 08:47:48,140 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutting down periodical [org.graylog2.periodical.VersionCheckThread].
2015-01-03 08:47:48,141 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutdown of periodical [org.graylog2.periodical.VersionCheckThread] complete, took <0ms>.
2015-01-03 08:47:48,153 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutting down periodical [org.graylog2.periodical.AlertScannerThread].
2015-01-03 08:47:48,153 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutdown of periodical [org.graylog2.periodical.AlertScannerThread] complete, took <0ms>.
2015-01-03 08:47:48,154 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutting down periodical [org.graylog2.periodical.BatchedElasticSearchOutputFlushThread].
2015-01-03 08:47:48,154 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutdown of periodical [org.graylog2.periodical.BatchedElasticSearchOutputFlushThread] complete, took <0ms>.
2015-01-03 08:47:48,178 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutting down periodical [org.graylog2.periodical.ClusterHealthCheckThread].
2015-01-03 08:47:48,179 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutdown of periodical [org.graylog2.periodical.ClusterHealthCheckThread] complete, took <0ms>.
2015-01-03 08:47:48,179 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutting down periodical [org.graylog2.periodical.IndexerClusterCheckerThread].
2015-01-03 08:47:48,180 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutdown of periodical [org.graylog2.periodical.IndexerClusterCheckerThread] complete, took <0ms>.
2015-01-03 08:47:48,180 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutting down periodical [org.graylog2.periodical.IndexRotationThread].
2015-01-03 08:47:48,180 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutdown of periodical [org.graylog2.periodical.IndexRotationThread] complete, took <0ms>.
2015-01-03 08:47:48,181 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutting down periodical [org.graylog2.periodical.IndexRetentionThread].
2015-01-03 08:47:48,181 INFO : org.graylog2.shared.initializers.PeriodicalsService - Shutdown of periodical [org.graylog2.periodical.IndexRetentionThread] complete, took <0ms>.
2015-01-03 08:47:48,184 WARN : org.graylog2.initializers.BufferSynchronizerService - Elasticsearch is unavailable. Not waiting to clear buffers and caches, as we have no healthy cluster.
2015-01-03 08:47:48,204 INFO : org.elasticsearch.node - [graylog2-server] stopping ...
2015-01-03 08:47:48,214 INFO : org.graylog2.initializers.OutputSetupService - Stopping output org.graylog2.outputs.BatchedElasticSearchOutput
2015-01-03 08:47:48,238 INFO : org.elasticsearch.node - [graylog2-server] stopped
2015-01-03 08:47:48,241 INFO : org.elasticsearch.node - [graylog2-server] closing ...
2015-01-03 08:47:48,291 INFO : org.elasticsearch.node - [graylog2-server] closed
2015-01-03 08:48:01,475 INFO : org.graylog2.shared.initializers.RestApiService - Adding security context factory: <org.graylog2.security.ShiroSecurityContextFactory@2a0eebf1>
2015-01-03 08:48:01,544 INFO : org.graylog2.shared.initializers.RestApiService - Started REST API at <http://127.0.0.1:12900/>
2015-01-03 08:48:01,547 INFO : org.graylog2.shared.initializers.RestApiService - Shutting down REST API at <http://127.0.0.1:12900/>
2015-01-03 08:48:01,564 ERROR: org.graylog2.Main - Graylog2 startup failed. Exiting. Exception was:
java.lang.IllegalStateException: Expected to be healthy after starting. The following services are not running: {STARTING=[RestApiService [STARTING]], FAILED=[IndexerSetupService [FAILED]]}
    at com.google.common.util.concurrent.ServiceManager$ServiceManagerState.checkHealthy(ServiceManager.java:710)
    at com.google.common.util.concurrent.ServiceManager$ServiceManagerState.awaitHealthy(ServiceManager.java:535)
    at com.google.common.util.concurrent.ServiceManager.awaitHealthy(ServiceManager.java:301)
    at org.graylog2.Main.main(Main.java:275)
2015-01-03 08:48:01,568 INFO : org.graylog2.shared.initializers.ServiceManagerListener - Services are now stopped.
2015-01-03 08:48:01,579 INFO : org.graylog2.Main - SIGNAL received. Shutting down.
2015-01-03 08:48:01,582 ERROR: org.graylog2.periodical.AbstractCacheWorkerThread - Exception while working on cache:
java.lang.IllegalStateException: Error while accessing database
    at org.graylog2.caches.DiskJournalCache.pop(DiskJournalCache.java:191)
    at org.graylog2.periodical.AbstractCacheWorkerThread.drainMessagesEnqueue(AbstractCacheWorkerThread.java:75)
    at org.graylog2.periodical.AbstractCacheWorkerThread.work(AbstractCacheWorkerThread.java:58)
    at org.graylog2.periodical.InputCacheWorkerThread$1.run(InputCacheWorkerThread.java:60)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalAccessError: already closed
    at org.mapdb.EngineWrapper$1.get(EngineWrapper.java:472)
    at org.mapdb.EngineWrapper.get(EngineWrapper.java:58)
    at org.mapdb.Atomic$Long.get(Atomic.java:315)
    at org.mapdb.Queues$SimpleQueue.poll(Queues.java:127)
    at org.mapdb.Queues$SimpleQueue.take(Queues.java:243)
    at org.graylog2.caches.DiskJournalCache.pop(DiskJournalCache.java:181)
    ... 4 more
2015-01-03 08:48:01,580 ERROR: org.graylog2.periodical.AbstractCacheWorkerThread - Exception while working on cache:
java.lang.IllegalStateException: Error while accessing database
    at org.graylog2.caches.DiskJournalCache.pop(DiskJournalCache.java:191)
    at org.graylog2.periodical.AbstractCacheWorkerThread.drainMessagesEnqueue(AbstractCacheWorkerThread.java:75)
    at org.graylog2.periodical.AbstractCacheWorkerThread.work(AbstractCacheWorkerThread.java:58)
    at org.graylog2.periodical.OutputCacheWorkerThread$1.run(OutputCacheWorkerThread.java:60)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalAccessError: already closed
    at org.mapdb.EngineWrapper$1.get(EngineWrapper.java:472)
    at org.mapdb.EngineWrapper.get(EngineWrapper.java:58)
    at org.mapdb.Atomic$Long.get(Atomic.java:315)
    at org.mapdb.Queues$SimpleQueue.poll(Queues.java:127)
    at org.mapdb.Queues$SimpleQueue.take(Queues.java:243)
    at org.graylog2.caches.DiskJournalCache.pop(DiskJournalCache.java:181)
    ... 4 more
2015-01-03 08:48:01,797 INFO : org.graylog2.system.shutdown.GracefulShutdown - Graceful shutdown initiated.
2015-01-03 08:48:01,806 INFO : org.graylog2.system.shutdown.GracefulShutdown - Node status: [Halting [LB:DEAD]]. Waiting <3sec> for possible load balancers to recognize state change.
2015-01-03 08:48:05,812 INFO : org.graylog2.system.shutdown.GracefulShutdown - Goodbye.

[bernd]

I just tested the vagrant setup yesterday to reproduce a different issue. It worked fine for me.

It looks like the initial provisioning of the vagrant box failed. Can you please vagrant destroy and vagrant up again and paste the log of the vagrant command here?

[bernd]

And yes, you are not supposed to do anything manually. 😃 All packages will be installed and setup automatically. Something failed regarding the provisioning and we have to find out what happened.

[mariussturm]

@fhemberger all the missing components are installed under /opt/graylog2. There is no need to install anything manually. However for some reasons your graylog2-server didn't startup correctly on the first try. Could you send us the output of the vagrant up command to debug this a little further?

[fhemberger]

My bad … destroyed the vm, did a fresh vagrant up again and now it works of cause. 😔

I compared the outputs of both vagrant up runs and they are absolutely identical, no error message or extra output. So I really can't tell what went wrong on the first run. But thanks for looking into it!

[lollisoft]

Hi,

I had the same issues on my Mac OS X and after a fourth try I got an instance running (including access to the management site).

I had some feeling of hungs with 100% at 170MB RAM usage of the VM. So it seems to be a race condition.