Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1345852

Summary: kibana pod crashes repeatedly: Request Timeout after 5000ms\n at null.<anonymous> (/usr/share/kibana/src/node_modules/elasticsearch/src/lib/transport.js:282:15
Product: OpenShift Container Platform Reporter: chunchen <chunchen>
Component: LoggingAssignee: Jeff Cantrill <jcantril>
Status: CLOSED ERRATA QA Contact: Xia Zhao <xiazhao>
Severity: low Docs Contact: Xia Zhao <xiazhao>
Priority: low    
Version: 3.2.1CC: aos-bugs, chunchen, pportant, rmeggins, vwalek, wsun, xiazhao
Target Milestone: ---Keywords: Regression
Target Release: 3.5.z   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: No Doc Update
Doc Text:
undefined
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-10-25 13:00:48 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description chunchen 2016-06-13 10:31:22 UTC
Description of problem:
After deploying Logging in a 3.2.1 environment , the kibana pod is crashing all the time

Version-Release number of selected component (if applicable):
openshift v3.2.1.1-1-g33fa4ea
kubernetes v1.2.0-36-g4a3f9c5
etcd 2.2.5

registry...com/openshift3/logging-auth-proxy      3.2.1
registry...com/openshift3/logging-elasticsearch   3.2.1
registry...com/openshift3/logging-fluentd         3.2.1
registry...com/openshift3/logging-kibana          3.2.1

How reproducible:
always

Steps to Reproduce:
1. Deploy the logging stack
oc secrets new logging-deployer nothing=/dev/

echo -e "apiVersion: v1
kind: ServiceAccount
metadata:
    name: logging-deployer
secrets:
- name: logging-deployer"| oc create -f -

oc policy add-role-to-user edit system:serviceaccount:chunlogging:logging-deployer
oadm policy add-cluster-role-to-user cluster-reader system:serviceaccount:chunlogging:aggregated-logging-fluentd
oadm policy add-scc-to-user privileged system:serviceaccount:chunlogging:aggregated-logging-fluentd

oc new-app logging-deployer-template -p ENABLE_OPS_CLUSTER=true,IMAGE_PREFIX=registry...com/openshift3/,KIBANA_HOSTNAME=<kibana-host-name>,KIBANA_OPS_HOSTNAME=<kibana-ops-host-name>,PUBLIC_MASTER_URL=https://<master-dns>:8443,ES_INSTANCE_RAM=1024M,ES_CLUSTER_SIZE=1,IMAGE_VERSION=3.2.1,MASTER_URL=https://<master-dns>:8443,MODE=install

oc process logging-support-template -n chunlogging -v IMAGE_VERSION=3.2.1| oc create -n chunlogging -f -

oc scale dc/logging-fluentd --replicas=1
oc scale rc/logging-fluentd-1 --replicas=1

2. Check the pod status and logs of kibana
oc get pods
oc logs logging-kibana-1-bge4a -c kibana

Actual results:
[chunchen@F17-CCY daily]$ oc get pod
NAME                              READY     STATUS             RESTARTS   AGE
logging-deployer-uerlo            0/1       Completed          0          45m
logging-es-0arijcdl-1-ge092       1/1       Running            0          41m
logging-es-ops-tmyrhik8-1-ava24   1/1       Running            0          41m
logging-fluentd-1-7yhm8           1/1       Running            0          27m
logging-kibana-1-bge4a            1/2       CrashLoopBackOff   8          40m
logging-kibana-ops-1-wlck8        1/2       CrashLoopBackOff   8          40m

[chunchen@F17-CCY daily]$ oc logs logging-kibana-1-bge4a -c kibana
{"name":"Kibana","hostname":"logging-kibana-1-bge4a","pid":8,"level":50,"err":{"message":"Request Timeout after 5000ms","name":"Error","stack":"Error: Request Timeout after 5000ms\n    at null.<anonymous> (/usr/share/kibana/src/node_modules/elasticsearch/src/lib/transport.js:282:15)\n    at Timer.listOnTimeout [as ontimeout] (timers.js:112:15)"},"msg":"","time":"2016-06-13T09:21:58.017Z","v":0}
{"name":"Kibana","hostname":"logging-kibana-1-bge4a","pid":8,"level":60,"err":{"message":"Request Timeout after 5000ms","name":"Error","stack":"Error: Request Timeout after 5000ms\n    at null.<anonymous> (/usr/share/kibana/src/node_modules/elasticsearch/src/lib/transport.js:282:15)\n    at Timer.listOnTimeout [as ontimeout] (timers.js:112:15)"},"msg":"","time":"2016-06-13T09:21:58.042Z","v":0}

Expected results:
Kibana should work fine.

Additional info:
[chunchen@F17-CCY scripts]$ oc logs logging-es-0arijcdl-1-ge092
+ mkdir -p /elasticsearch/logging-es
+ ln -s /etc/elasticsearch/keys/searchguard.key /elasticsearch/logging-es/searchguard_node_key.key
+ regex='^([[:digit:]]+)([GgMm])$'
+ [[ 1024M =~ ^([[:digit:]]+)([GgMm])$ ]]
+ num=1024
+ unit=M
+ [[ M =~ [Gg] ]]
+ [[ 1024 -lt 512 ]]
+ ES_JAVA_OPTS='-Des.path.home=/usr/share/elasticsearch -Des.config=/etc/elasticsearch/elasticsearch.yml -Xms256M -Xmx512m'
+ /usr/share/elasticsearch/bin/elasticsearch
[2016-06-13 04:42:34,842][INFO ][node                     ] [Dragon Lord] version[1.5.2], pid[8], build[d761af4/2015-07-24T22:21:43Z]
[2016-06-13 04:42:34,844][INFO ][node                     ] [Dragon Lord] initializing ...
[2016-06-13 04:42:56,468][INFO ][plugins                  ] [Dragon Lord] loaded [searchguard, openshift-elasticsearch-plugin, cloud-kubernetes], sites []
[2016-06-13 04:46:45,393][INFO ][node                     ] [Dragon Lord] initialized
[2016-06-13 04:46:45,394][INFO ][node                     ] [Dragon Lord] starting ...
[2016-06-13 04:46:51,410][INFO ][transport                ] [Dragon Lord] bound_address {inet[/0:0:0:0:0:0:0:0:9300]}, publish_address {inet[/10.1.1.11:9300]}
[2016-06-13 04:46:53,818][INFO ][discovery                ] [Dragon Lord] logging-es/_Noj3fRJQCKuBFlfhHRIcw
[2016-06-13 04:46:54,076][ERROR][io.fabric8.elasticsearch.plugin.acl.DynamicACLFilter] [Dragon Lord] Error checking ACL when seeding
org.elasticsearch.cluster.block.ClusterBlockException: blocked by: [SERVICE_UNAVAILABLE/1/state not recovered / initialized];
	at org.elasticsearch.cluster.block.ClusterBlocks.globalBlockedException(ClusterBlocks.java:151)
	at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction.checkGlobalBlock(TransportShardSingleOperationAction.java:103)
	at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction$AsyncSingleAction.<init>(TransportShardSingleOperationAction.java:132)
	at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction$AsyncSingleAction.<init>(TransportShardSingleOperationAction.java:116)
	at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction.doExecute(TransportShardSingleOperationAction.java:89)
	at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction.doExecute(TransportShardSingleOperationAction.java:55)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:167)
	at io.fabric8.elasticsearch.plugin.KibanaUserReindexAction.apply(KibanaUserReindexAction.java:74)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:165)
	at com.floragunn.searchguard.filter.SearchGuardActionFilter.apply0(SearchGuardActionFilter.java:145)
	at com.floragunn.searchguard.filter.SearchGuardActionFilter.apply(SearchGuardActionFilter.java:90)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:165)
	at com.floragunn.searchguard.filter.AbstractActionFilter.apply(AbstractActionFilter.java:105)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:165)
	at com.floragunn.searchguard.filter.AbstractActionFilter.apply(AbstractActionFilter.java:105)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:165)
	at com.floragunn.searchguard.filter.AbstractActionFilter.apply(AbstractActionFilter.java:105)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:165)
	at org.elasticsearch.action.support.ActionFilter$Simple.apply(ActionFilter.java:64)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:165)
	at io.fabric8.elasticsearch.plugin.ActionForbiddenActionFilter.apply(ActionForbiddenActionFilter.java:48)
	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:165)
	at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:82)
	at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:55)
	at org.elasticsearch.client.node.NodeClient.execute(NodeClient.java:90)
	at org.elasticsearch.client.support.AbstractClient.get(AbstractClient.java:188)
	at io.fabric8.elasticsearch.plugin.acl.DynamicACLFilter.loadAcl(DynamicACLFilter.java:251)
	at io.fabric8.elasticsearch.plugin.acl.DynamicACLFilter.seedInitialACL(DynamicACLFilter.java:303)
	at io.fabric8.elasticsearch.plugin.acl.DynamicACLFilter.onSearchGuardACLActionRequest(DynamicACLFilter.java:118)
	at io.fabric8.elasticsearch.plugin.acl.DefaultACLNotifierService$1.run(DefaultACLNotifierService.java:64)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
<---------------snip-------------->
[2016-06-13 04:47:29,950][INFO ][http                     ] [Dragon Lord] bound_address {inet[/0:0:0:0:0:0:0:0:9200]}, publish_address {inet[/10.1.1.11:9200]}
[2016-06-13 04:47:29,950][INFO ][node                     ] [Dragon Lord] started
[2016-06-13 04:47:37,386][INFO ][gateway                  ] [Dragon Lord] recovered [0] indices into cluster_state
[2016-06-13 04:48:20,538][WARN ][monitor.jvm              ] [Dragon Lord] [gc][young][53][3] duration [8.2s], collections [1]/[8.5s], total [8.2s]/[14.8s], memory [90.6mb]->[31.9mb]/[503.6mb], all_pools {[young] [66.5mb]->[527.1kb]/[66.5mb]}{[survivor] [8.3mb]->[8.3mb]/[8.3mb]}{[old] [15.7mb]->[23.1mb]/[428.8mb]}
[2016-06-13 04:49:02,196][INFO ][cluster.metadata         ] [Dragon Lord] [.searchguard.logging-es-0arijcdl-1-ge092] creating index, cause [auto(index api)], templates [], shards [5]/[1], mappings [ac]
[2016-06-13 04:49:44,261][INFO ][cluster.metadata         ] [Dragon Lord] [.searchguard.logging-es-0arijcdl-1-ge092] update_mapping [ac] (dynamic)
[2016-06-13 04:58:41,886][INFO ][cluster.metadata         ] [Dragon Lord] [xiazhaotest.d59d1428-3124-11e6-8eec-42010af0000f.2016.06.13] creating index, cause [auto(bulk api)], templates [], shards [5]/[1], mappings [fluentd]
[2016-06-13 04:59:53,920][INFO ][cluster.metadata         ] [Dragon Lord] [xiazhaotest.d59d1428-3124-11e6-8eec-42010af0000f.2016.06.13] update_mapping [fluentd] (dynamic)
[2016-06-13 05:06:32,945][WARN ][monitor.jvm              ] [Dragon Lord] [gc][young][805][9] duration [4.3s], collections [1]/[5s], total [4.3s]/[20.3s], memory [123.8mb]->[66.8mb]/[503.6mb], all_pools {[young] [66.5mb]->[7.4mb]/[66.5mb]}{[survivor] [4.5mb]->[6.5mb]/[8.3mb]}{[old] [52.8mb]->[52.8mb]/[428.8mb]}
[2016-06-13 05:07:51,616][INFO ][cluster.metadata         ] [Dragon Lord] [chunlogging.e5014684-3141-11e6-8eec-42010af0000f.2016.06.13] creating index, cause [auto(bulk api)], templates [], shards [5]/[1], mappings [fluentd]
[2016-06-13 05:08:20,584][WARN ][monitor.jvm              ] [Dragon Lord] [gc][young][865][11] duration [1.8s], collections [1]/[2.2s], total [1.8s]/[22.8s], memory [128.6mb]->[65.1mb]/[503.6mb], all_pools {[young] [65.2mb]->[1mb]/[66.5mb]}{[survivor] [8.3mb]->[5.3mb]/[8.3mb]}{[old] [55mb]->[58.7mb]/[428.8mb]}
[2016-06-13 05:08:35,208][INFO ][cluster.metadata         ] [Dragon Lord] [install-test.671246bc-310d-11e6-8eec-42010af0000f.2016.06.13] creating index, cause [auto(bulk api)], templates [], shards [5]/[1], mappings [fluentd]
[2016-06-13 05:11:23,659][WARN ][monitor.jvm              ] [Dragon Lord] [gc][young][925][12] duration [9.8s], collections [1]/[13.8s], total [9.8s]/[32.6s], memory [129.3mb]->[70.4mb]/[503.6mb], all_pools {[young] [65.3mb]->[650.1kb]/[66.5mb]}{[survivor] [5.3mb]->[8.3mb]/[8.3mb]}{[old] [58.7mb]->[61.4mb]/[428.8mb]}
[2016-06-13 05:12:45,164][WARN ][monitor.jvm              ] [Dragon Lord] [gc][young][958][13] duration [2.8s], collections [1]/[3.4s], total [2.8s]/[35.4s], memory [125.5mb]->[78.2mb]/[503.6mb], all_pools {[young] [55.8mb]->[1.6mb]/[66.5mb]}{[survivor] [8.3mb]->[7.4mb]/[8.3mb]}{[old] [61.4mb]->[69.1mb]/[428.8mb]}
[2016-06-13 05:13:47,892][WARN ][monitor.jvm              ] [Dragon Lord] [gc][young][976][15] duration [7.6s], collections [1]/[15.5s], total [7.6s]/[43.1s], memory [145.1mb]->[119mb]/[503.6mb], all_pools {[young] [65.2mb]->[13.9mb]/[66.5mb]}{[survivor] [6.1mb]->[5.9mb]/[8.3mb]}{[old] [73.7mb]->[99.1mb]/[428.8mb]}
[2016-06-13 05:14:16,718][INFO ][cluster.metadata         ] [Dragon Lord] [chunlogging.e5014684-3141-11e6-8eec-42010af0000f.2016.06.13] update_mapping [fluentd] (dynamic)
[2016-06-13 05:15:42,759][WARN ][monitor.jvm              ] [Dragon Lord] [gc][young][1017][20] duration [2.1s], collections [1]/[2.3s], total [2.1s]/[45.5s], memory [153.4mb]->[91.8mb]/[503.6mb], all_pools {[young] [65.9mb]->[359.5kb]/[66.5mb]}{[survivor] [8.3mb]->[8.3mb]/[8.3mb]}{[old] [79.1mb]->[83.1mb]/[428.8mb]}
<--------------snip-------------->

Comment 6 Peter Portante 2017-05-09 01:12:25 UTC
Still a problem?

Comment 7 Xia Zhao 2017-05-11 07:24:36 UTC
@Peter

The verification work on 3.6.0 was blocked by this bz https://bugzilla.redhat.com/show_bug.cgi?id=1439451

However , when I tested on OCP 3.5.0 with the latest images, didn't encounter the original issue inside kibana pod:
# oc get po
NAME                          READY     STATUS    RESTARTS   AGE
logging-curator-1-nmqjs       1/1       Running   0          58m
logging-es-cxo0i5m4-1-ss4hp   1/1       Running   0          58m
logging-fluentd-0fxr0         1/1       Running   0          58m
logging-fluentd-c1sfm         1/1       Running   0          58m
logging-kibana-1-3j8mq        2/2       Running   0          58m

Images tested with:
openshift3/logging-kibana    5264d47e960a
openshift3/logging-elasticsearch    d324b405d1cb
openshift3/logging-fluentd    1ccfd59193a6
openshift3/logging-curator    f9b7d8474851
openshift3/logging-auth-proxy    304b75191599

# openshift version
openshift v3.5.5.14
kubernetes v1.5.2+43a9be4
etcd 3.1.0


Based on the above test result, please feel free to transfer back to ON_QA for closure.

Comment 8 Xia Zhao 2017-05-15 05:44:41 UTC
Set to verified according to the test result for the latest 3.5 on comment #7.

Comment 10 errata-xmlrpc 2017-10-25 13:00:48 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:3049