Kibana not starting. Stuck at "Optimizing and caching bundles...." after upgrade


#1

Looks like I have been hit with a rather common issue. Though in my case I am not using any third party plugins.

Details:
Machine: Red Hat Enterprise Linux Server release 7.4
RAM: 8GB
It also hosts Elasticsearch (It is not production setup)

Action: Upgraded Kibana from 6.3.2-1 to 6.5.1-1. Upgrade went smooth

Result: Kibana never came up. On checking the logs this was the message at which it was stuck. This message kept getting repeated after some lengthy interval.

{"type":"log","@timestamp":"2018-11-22T11:39:50Z","tags":["plugin","warning"],"pid":18789,"path":"/usr/share/kibana/src/core_plugins/spy_modes","message":"Skipping non-plugin directory at /usr/share/kibana/src/core_plugins/spy_modes"}
{"type":"log","@timestamp":"2018-11-22T11:39:51Z","tags":["info","optimize"],"pid":18789,"message":"Optimizing and caching bundles for ml, stateSessionStorageRedirect, status_page, timelion, graph, monitoring, space_selector, dashboardViewer, apm, canvas, infra and kibana. This may take a few minutes"}

To get some more details I tried the verbose trick.

/usr/share/kibana/bin/kibana --verbose -c /etc/kibana/kibana.yml

This is what I got.

{"type":"log","@timestamp":"2018-11-22T03:25:10Z","tags":["debug","http","server"],"pid":20336,"message":"http server running at http://helloworld:5998"}
{"type":"log","@timestamp":"2018-11-22T03:25:10Z","tags":["debug","legacy","service"],"pid":20336,"message":"starting legacy service"}
{"type":"log","@timestamp":"2018-11-22T03:25:11Z","tags":["debug","config"],"pid":20336,"message":"Marking config path as handled: server"}
{"type":"log","@timestamp":"2018-11-22T03:25:11Z","tags":["debug","legacy","proxy"],"pid":20336,"message":"Event is being forwarded: connection"}
{"type":"log","@timestamp":"2018-11-22T03:25:11Z","tags":["debug","legacy","proxy"],"pid":20336,"message":"Event is being forwarded: connection"}
{"type":"log","@timestamp":"2018-11-22T03:25:22Z","tags":["plugin","debug"],"pid":20336,"path":"/usr/share/kibana/node_modules/x-pack","message":"Found plugin at /usr/share/kibana/node_modules/x-pack"}
{"type":"log","@timestamp":"2018-11-22T03:25:11Z","tags":["debug","legacy","service"],"pid":20336,"message":"Kibana server is not ready yet POST:/elasticsearch/_msearch."}
{"type":"log","@timestamp":"2018-11-22T03:25:22Z","tags":["debug","legacy","proxy"],"pid":20336,"message":"\"getConnections\" has been called."}
.
.
.
.
{"type":"log","@timestamp":"2018-11-22T03:26:54Z","tags":["debug","legacy","proxy"],"pid":20336,"message":"\"getConnections\" has been called."}
{"type":"ops","@timestamp":"2018-11-22T03:26:54Z","tags":[],"pid":20336,"os":{"load":[1.78955078125,1.2578125,1.49365234375],"mem":{"total":8203014144,"free":736821248},"uptime":2904375},"proc":{"uptime":105.087,"mem":{"rss":789721088,"heapTotal":731795456,"heapUsed":469409224,"external":28132358},"delay":106.64260482788086},"load":{"requests":{},"concurrents":{"5601":2},"responseTimes":{},"sockets":{"http":{"total":0},"https":{"total":0}}},"message":"memory: 447.7MB uptime: 0:01:45 load: [1.79 1.26 1.49] delay: 106.643"}
{"type":"log","@timestamp":"2018-11-22T03:26:59Z","tags":["debug","legacy","proxy"],"pid":20336,"message":"\"getConnections\" has been called."}
{"type":"ops","@timestamp":"2018-11-22T03:26:59Z","tags":[],"pid":20336,"os":{"load":[1.7265625,1.25341796875,1.4912109375],"mem":{"total":8203014144,"free":719556608},"uptime":2904380},"proc":{"uptime":110.098,"mem":{"rss":806907904,"heapTotal":751693824,"heapUsed":420399104,"external":24737116},"delay":46.86207103729248},"load":{"requests":{},"concurrents":{"5601":2},"responseTimes":{},"sockets":{"http":{"total":0},"https":{"total":0}}},"message":"memory: 400.9MB uptime: 0:01:50 load: [1.73 1.25 1.49] delay: 46.862"}
{"type":"log","@timestamp":"2018-11-22T03:27:04Z","tags":["debug","legacy","proxy"],"pid":20336,"message":"\"getConnections\" has been called."}
{"type":"ops","@timestamp":"2018-11-22T03:27:04Z","tags":[],"pid":20336,"os":{"load":[1.66845703125,1.2490234375,1.48876953125],"mem":{"total":8203014144,"free":702382080},"uptime":2904385},"proc":{"uptime":115.111,"mem":{"rss":823590912,"heapTotal":767447040,"heapUsed":585194408,"external":25700873},"delay":16.464394092559814},"load":{"requests":{},"concurrents":{"5601":2},"responseTimes":{},"sockets":{"http":{"total":0},"https":{"total":0}}},"message":"memory: 558.1MB uptime: 0:01:55 load: [1.67 1.25 1.49] delay: 16.464"}
{"type":"log","@timestamp":"2018-11-22T03:27:11Z","tags":["debug","legacy","proxy"],"pid":20336,"message":"\"getConnections\" has been called."}
{"type":"ops","@timestamp":"2018-11-22T03:27:12Z","tags":[],"pid":20336,"os":{"load":[1.5654296875,1.2412109375,1.48388671875],"mem":{"total":8203014144,"free":629055488},"uptime":2904391},"proc":{"uptime":121.483,"mem":{"rss":896516096,"heapTotal":839262208,"heapUsed":505503048,"external":19850987},"delay":804.1342277526855},"load":{"requests":{},"concurrents":{"5601":2},"responseTimes":{},"sockets":{"http":{"total":0},"https":{"total":0}}},"message":"memory: 482.1MB uptime: 0:02:01 load: [1.57 1.24 1.48] delay: 804.134"}
{"type":"log","@timestamp":"2018-11-22T03:27:14Z","tags":["debug","legacy","proxy"],"pid":20336,"message":"Event is being forwarded: connection"}
{"type":"log","@timestamp":"2018-11-22T03:27:14Z","tags":["debug","legacy","service"],"pid":20336,"message":"Kibana server is not ready yet POST:/elasticsearch/_msearch."}
{"type":"log","@timestamp":"2018-11-22T03:27:16Z","tags":["debug","legacy","proxy"],"pid":20336,"message":"\"getConnections\" has been called."}
{"type":"ops","@timestamp":"2018-11-22T03:27:16Z","tags":[],"pid":20336,"os":{"load":[1.52001953125,1.2373046875,1.4814453125],"mem":{"total":8203014144,"free":614453248},"uptime":2904396},"proc":{"uptime":126.511,"mem":{"rss":910381056,"heapTotal":854966272,"heapUsed":541285688,"external":18662628},"delay":5.138576030731201},"load":{"requests":{},"concurrents":{"5601":2},"responseTimes":{},"sockets":{"http":{"total":0},"https":{"total":0}}},"message":"memory: 516.2MB uptime: 0:02:07 load: [1.52 1.24 1.48] delay: 5.139"}

I am kind of confused as how to proceed. There should be some error message hidden somewhere in the logs which is some how escaping me.

EDIT: I did use to have memory issue and there was this time when indices got marked as read only. When it was not working then as a last resort I tried this command on also but of no avail.

curl -X PUT "helloworld:5998/*/_settings" -H 'Content-Type: application/json' -d' {"index.blocks.read_only_allow_delete": null}'


(Marius Dragomir) #2

you can try and delete the optimize folder in the kibana folder and restarting Kibana. There have been improvements to not having the optimization process failing in Kibana.


#3

After deleting the folder sudo systemctl start kibana.service is failing.

Manually starting it via
sudo /usr/share/kibana/bin/kibana --verbose -c /etc/kibana/kibana.yml

gives the same result

{"type":"log","@timestamp":"2018-11-22T19:20:49Z","tags":["debug","legacy","proxy"],"pid":16136,"message":"\"getConnections\" has been called."} {"type":"ops","@timestamp":"2018-11-22T19:20:50Z","tags":[],"pid":16136,"os":{"load":[2.04345703125,1.3427734375,1.43994140625],"mem":{"total":8203014144,"free":2035298304},"uptime":2961610},"proc":{"uptime":116.141,"mem":{"rss":816234496,"heapTotal":760107008,"heapUsed":511865296,"external":24159860},"delay":105.67372703552246},"load":{"requests":{},"concurrents":{"5601":2},"responseTimes":{},"sockets":{"http":{"total":0},"https":{"total":0}}},"message":"memory: 488.2MB uptime: 0:01:56 load: [2.04 1.34 1.44] delay: 105.674"} {"type":"log","@timestamp":"2018-11-22T19:20:56Z","tags":["debug","legacy","proxy"],"pid":16136,"message":"\"getConnections\" has been called."} {"type":"log","@timestamp":"2018-11-22T19:20:56Z","tags":["debug","legacy","proxy"],"pid":16136,"message":"Event is being forwarded: connection"} {"type":"ops","@timestamp":"2018-11-22T19:20:56Z","tags":[],"pid":16136,"os":{"load":[2.0400390625,1.353515625,1.44287109375],"mem":{"total":8203014144,"free":2018521088},"uptime":2961616},"proc":{"uptime":122.229,"mem":{"rss":832659456,"heapTotal":776347648,"heapUsed":474279392,"external":19943600},"delay":803.4226069450378},"load":{"requests":{},"concurrents":{"5601":2},"responseTimes":{},"sockets":{"http":{"total":0},"https":{"total":0}}},"message":"memory: 452.3MB uptime: 0:02:02 load: [2.04 1.35 1.44] delay: 803.423"} {"type":"log","@timestamp":"2018-11-22T19:20:56Z","tags":["debug","legacy","proxy"],"pid":16136,"message":"Event is being forwarded: connection"} {"type":"log","@timestamp":"2018-11-22T19:20:59Z","tags":["debug","legacy","service"],"pid":16136,"message":"Kibana server is not ready yet GET:/app/kibana."} {"type":"log","@timestamp":"2018-11-22T19:20:59Z","tags":["debug","legacy","service"],"pid":16136,"message":"Kibana server is not ready yet GET:/favicon.ico."} {"type":"log","@timestamp":"2018-11-22T19:21:01Z","tags":["debug","legacy","proxy"],"pid":16136,"message":"\"getConnections\" has been called."} {"type":"ops","@timestamp":"2018-11-22T19:21:01Z","tags":[],"pid":16136,"os":{"load":[2.11669921875,1.380859375,1.451171875],"mem":{"total":8203014144,"free":1988173824},"uptime":2961621},"proc":{"uptime":127.379,"mem":{"rss":862781440,"heapTotal":808828928,"heapUsed":507342480,"external":19505461},"delay":67.46098756790161},"load":{"requests":{},"concurrents":{"5601":4},"responseTimes":{},"sockets":{"http":{"total":0},"https":{"total":0}}},"message":"memory: 483.8MB uptime: 0:02:07 load: [2.12 1.38 1.45] delay: 67.461"}


#4

The reason for the kibana service failing to start what that optimize folder was re created but with root permissions. I changed the group and owner to kibana. And now it is back to the same error of optimizing.

{"type":"log","@timestamp":"2018-11-22T19:31:17Z","tags":["plugin","warning"],"pid":17035,"path":"/usr/share/kibana/src/core_plugins/spy_modes","message":"Skipping non-plugin directory at /usr/share/kibana/src/core_plugins/spy_modes"} {"type":"log","@timestamp":"2018-11-22T19:31:18Z","tags":["info","optimize"],"pid":17035,"message":"Optimizing and caching bundles for ml, stateSessionStorageRedirect, status_page, timelion, graph, monitoring, space_selector, dashboardViewer, apm, canvas, infra and kibana. This may take a few minutes"}


#5

same issue here ... after fixing permissions and restarting kibana, over hours no result ...
some files in optimization folder are created, but as I can compare with an 6.4.3 installation
they are not complete ... some with zero size

I am on CentOS / ( 3.10.0-862.14.4.el7.x86_64 )

-rw-r--r-- 1 kibana kibana 1577 23. Nov 07:17 apm.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 apm.style.css
-rw-r--r-- 1 kibana kibana 1578 23. Nov 07:17 canvas.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 canvas.style.css
-rw-r--r-- 1 kibana kibana 1599 23. Nov 07:17 dashboardViewer.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 dashboardViewer.style.css
-rw-r--r-- 1 kibana kibana 1577 23. Nov 07:17 graph.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 graph.style.css
-rw-r--r-- 1 kibana kibana 1577 23. Nov 07:17 infra.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 infra.style.css
-rw-r--r-- 1 kibana kibana 1581 23. Nov 07:17 kibana.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 kibana.style.css
-rw-r--r-- 1 kibana kibana 1574 23. Nov 07:17 ml.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 ml.style.css
-rw-r--r-- 1 kibana kibana 1589 23. Nov 07:17 monitoring.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 monitoring.style.css
-rw-r--r-- 1 kibana kibana 1595 23. Nov 07:17 space_selector.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 space_selector.style.css
-rw-r--r-- 1 kibana kibana 1598 23. Nov 07:17 stateSessionStorageRedirect.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 stateSessionStorageRedirect.style.css
-rw-r--r-- 1 kibana kibana 1591 23. Nov 07:17 status_page.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 status_page.style.css
-rw-r--r-- 1 kibana kibana 1580 23. Nov 07:17 timelion.entry.js
-rw-r--r-- 1 kibana kibana 0 23. Nov 07:17 timelion.style.css


#6

Is this a known issue? If need be then I am happy to create a bug for this.


#7

Some more info on this
I tried increasing the memory for node.js.
export NODE_OPTIONS="--max-old-space-size=5000"

Still no luck. However using top command shows that node is using quite a bit of resources.

And then there was a crash.

[myserver ~]$ sudo /usr/share/kibana/bin/kibana --verbose -c /etc/kibana/kibana.yml

<--- Last few GCs --->

[30204:0x38bdb90]   890429 ms: Mark-sweep 1309.1 (1453.2) -> 1309.1 (1454.2) MB, 1509.8 / 0.0 ms  allocation failure GC in old space requested
[30204:0x38bdb90]   891989 ms: Mark-sweep 1309.1 (1454.2) -> 1309.1 (1416.2) MB, 1560.4 / 0.0 ms  last resort GC in old space requested
[30204:0x38bdb90]   893555 ms: Mark-sweep 1309.1 (1416.2) -> 1309.1 (1416.2) MB, 1566.2 / 0.0 ms  last resort GC in old space requested


<--- JS stacktrace --->

==== JS stack trace =========================================

Security context: 0x28d66ae25879 <JSObject>
    0: builtin exit frame: lastIndexOf(this=0x16726838f3c1 <Very long string[4569717]>,0x1d5dd118ca51 <String[1]\: \n>)

    1: has_nlb(aka has_nlb) [0xcbd32e022d1 <undefined>:5970] [bytecode=0x1c7895855f29 offset=15](this=0xcbd32e022d1 <undefined>)
    2: /* anonymous */(aka /* anonymous */) [0xcbd32e022d1 <undefined>:6070] [bytecode=0x3235f1f5d819 offset=60](this=0xcbd32e022d1 <undefined>,c=0x...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - JavaScript heap out of memory
 1: node::Abort() [/usr/share/kibana/bin/../node/bin/node]
 2: 0x8c21ec [/usr/share/kibana/bin/../node/bin/node]
 3: v8::Utils::ReportOOMFailure(char const*, bool) [/usr/share/kibana/bin/../node/bin/node]
 4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [/usr/share/kibana/bin/../node/bin/node]
 5: v8::internal::Factory::NewRawTwoByteString(int, v8::internal::PretenureFlag) [/usr/share/kibana/bin/../node/bin/node]
 6: v8::internal::String::SlowFlatten(v8::internal::Handle<v8::internal::ConsString>, v8::internal::PretenureFlag) [/usr/share/kibana/bin/../node/bin/node]
 7: v8::internal::String::Flatten(v8::internal::Handle<v8::internal::String>, v8::internal::PretenureFlag) [/usr/share/kibana/bin/../node/bin/node]
 8: v8::internal::String::LastIndexOf(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>) [/usr/share/kibana/bin/../node/bin/node]
 9: v8::internal::Builtin_StringPrototypeLastIndexOf(int, v8::internal::Object**, v8::internal::Isolate*) [/usr/share/kibana/bin/../node/bin/node]
10: 0x527c5a0697d
Aborted

Weird as it may sound, looks like progress. Any pointers?


#8

Just as the last resort I downgraded the Kibana to 6.4.3. It is working.
But since Elasticsearch was already upgraded to 6.5.1 I am now seeing

"message":"You're running Kibana 6.4.3 with some different versions of Elasticsearch. Update Kibana or Elasticsearch to the same version to prevent compatibility issues: v6.5.1

Will plan on downgrade now for Elasticsearch.

@jarpy : Any pointers to try out something before I do that?


(Ian Gabes) #9

We are also running into this problem. I upgraded my elasticsearch clusters to 6.5.1 from 5.6, then followed with my kibana installs to move to 6.5.1 as well also from 5.6.

I then downgraded my kibana install to 6.5.0. to see if that would help at all, but it didn't immediately solve the issue. After following some of the steps i found in various github issues and in this thread, I added the above export NODE_OPTIONS="--max-old-space-size=5000"

This allowed me to uncover the error discovered in this issue: https://github.com/elastic/kibana/issues/25728 (which I believe OP just linked here).

After clearing out xpack related configuration items left over from a previous xpack installation, I was able to start kibana after ~5 minutes of compile time. This solution was detailed in the above github issue. Here are the configuration lines I deleted:

TO DELETE:

xpack.security.enabled: false
xpack.graph.enabled: false
xpack.reporting.enabled: false

I find it odd that I had to increase the about of memory node could use before uncovering the actual error message, I guess this is a two for one special :sweat_smile:

I will go ahead and assume that upgrading back to kibana 6.5.1 will also function if I use the correct config files.


(Todd Lyons) #10

I spent 2 days trying to build kibana docker images with varying degrees of failure. One common issue is that Kibana spins into an "optimization" routine if you change anything about the xpack configuration. I found that setting nothing concerning xpack.* in the kibana yaml file resulted in immediate start-up due to no optimization being required. So, may I suggest to remove (comment out) everything xpack.* and start it up and see what happens? I suggest that you'll need to restore the optimization folder to however the installation process originally created it.


#11

I can report the same here.
Downgraded to 6.4.3 (after 24 hours of "optimizing") and it's working fine now. Hopefully this gets fixed in future releases


#12

as newby on elastic, I today start a fresh kibana installation on a new centos ... kibana starts up quit well. I tar.gz the /usr/share/kibana folder and extract it to the system I had the problems and ... now running ...

I went back one snapshot and completely deleted everything which belongs to kibana and did a reinstallation ... running into the same issue ... still investigating ...


(Rohit Jain) #13

I have just upgrade kibana from 6.4.0 to 6.5.1 but it gets stuck in optimization.
I am using search guard instead of xpack.security feature. So I disable it.

xpack.security.enabled: false

I have spent 24 hrs in optimization but still stuck . Any suggestion how to stop it.


(Rohit Jain) #14

@IanGabes , above configuration is not working. Should i downgrade kibana and ES to 6.4.0 ?


(Rohit Jain) #15

All things get sorted when we remove old indices on ES related to kibana.


#16

Upgrading to Elasticsearch 6.5.2 and Kibana 6.5.2 solved the issue.
Cheers.