Bug 1344644

https://issues.jboss.org/browse/WFCORE-1585 should not be affecting the OSE images (since we use EAP and not Wildfly).

The issue is actually because the script which starts EAP has an issue where it includes stdout but not stdin. I know this is fixed in OSE 3.2, and I thought it was fixed in the 3.1.1 images.

EAP has same problem and this issue also happens with 3.2 release.

https://bugzilla.redhat.com/show_bug.cgi?id=1344644

Oops, wrong link in the previous comment. This is correct one.

https://bugzilla.redhat.com/show_bug.cgi?id=1345816

@Takayoshi can you please explain what exactly you are seeing with the 3.2 images that is incorrect and what we should be seeing instead? For 3.1 we did have a similar issue, but that issue has been resolved (eg what we have to do for https://access.redhat.com/solutions/2329131 should no longer be the case).

What we are seeing is:

$ oc logs hawkular-metrics-l6t69 | grep EAP
$ oc logs hawkular-metrics-l6t69 | grep Metrics

What we expect is this output with the "oc logs". This is workaround version using "oc exec ... cat".

$ oc exec hawkular-metrics-l6t69 cat /opt/eap/standalone/log/server.log | grep EAP
22:20:07,490 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015874: JBoss EAP 6.4.4.GA (AS 7.5.4.Final-redhat-4) started in 15426ms - Started 267 of 303 services (62 services are lazy, passive or on-demand)

$ oc exec hawkular-metrics-l6t69 cat /opt/eap/standalone/log/server.log | grep Metrics
22:20:06,633 INFO  [org.hawkular.metrics.api.jaxrs.MetricsServiceLifecycle] (metricsservice-lifecycle-thread) HAWKMETRICS200002: Initializing metrics service
22:20:11,805 INFO  [org.hawkular.metrics.api.jaxrs.HawkularMetricsRestApp] (http-/0.0.0.0:8080-2) HAWKMETRICS200001: Hawkular Metrics starting
22:20:11,808 INFO  [org.jboss.resteasy.resteasy_jaxrs.i18n] (http-/0.0.0.0:8080-2) RESTEASY000320: Deploying javax.ws.rs.core.Application: class org.hawkular.metrics.api.jaxrs.HawkularMetricsRestApp$Proxy$_$$_WeldClientProxy
22:20:11,818 INFO  [org.hawkular.metrics.api.jaxrs.HawkularMetricsRestApp] (http-/0.0.0.0:8080-2) HAWKMETRICS200001: Hawkular Metrics starting
22:20:11,818 INFO  [org.hawkular.metrics.api.jaxrs.HawkularMetricsRestApp] (http-/0.0.0.0:8080-2) Virtual clock is disabled
22:20:11,819 INFO  [org.hawkular.metrics.api.jaxrs.HawkularMetricsRestApp] (http-/0.0.0.0:8080-2) Virtual clock is disabled
22:20:20,487 INFO  [org.hawkular.metrics.core.impl.MetricsServiceImpl] (metricsservice-lifecycle-thread) HAWKMETRICS100001: Using a key space of 'hawkular_metrics'
22:20:20,533 INFO  [org.hawkular.metrics.api.jaxrs.MetricsServiceLifecycle] (metricsservice-lifecycle-thread) HAWKMETRICS200005: Metrics service started

Ok, I have looked into this a bit more, and there is a bit of misinformation going on here. 

The issues linked here: https://issues.jboss.org/browse/WFCORE-1585 does not affect our components. We provide out own standalone.xml file which doesn't have the ASYNC attribute applied to console handler.

Our components work the same way as running this on an unmodified EAP/Wildfly instance. The console logs and server.log are different when running EAP/Wildfly, this is not something special which happens in our setup. But we should probably handle this better.

The issue listed https://access.redhat.com/solutions/2329131 is correct in that there was an issue with older metric containers, but its root cause is wrong. The issue had to do with this line (https://github.com/openshift/origin-metrics/blob/master/hawkular-metrics/hawkular-metrics-wrapper.sh#L74), one of our older scripts didn't include both stdout and stderr.

But, we should be handling this a bit better so that the console logs match the server.log values. All that needs to be done for this is for us to add in our own logging.properties file and change 'handler.CONSOLE.level=INFO' to 'handler.CONSOLE.level=ALL' and then console logs will match server.log.

Hmm, actually this is behaving a bit differently with our OSE images, even with the fix to the wrapper script. It looks like we will need to handling this a bit differently with the OSE images.

> The issues linked here: https://issues.jboss.org/browse/WFCORE-1585 does not affect our components. We provide out own standalone.xml file which doesn't have the ASYNC attribute applied to console handler.

The hawkular-metrics image uses same setup as WFCORE-1585 (and in fact WFCORE-1585 is created because of the hawkular-metrics image issue). logging.properties with ASYNC/CONSOLE and standalone.xml with FILE and CONSOLE. This is identical issue.

Created attachment 1168387 [details]
OSE 3.1.1 Standalone.xml

Created attachment 1168388 [details]
OSE 3.1.1 logging.properties

I am a bit confused here. The logging.properties and standalone.xml files pulled from our OSE images (attached) do not contain an ASYNC property for logging. This should mean that WFCORE-1585 does not affect our images.

Can you please explain what I am missing here?

If we change handler.CONSOLE.level in logging.properties from INFO to ALL, then our console logs match the server.logs (since the server.log is configure to also use ALL).

Without that change then there are slight differences between the console logs and server.log, which is to be expected and is how it works out of the box with WildFly/EAP.

I'm not sure how do you get that file. Did you get it after the boot?

$ docker run --rm -it registry.access.redhat.com/openshift3/metrics-hawkular-metrics:3.1.1 cat /opt/eap/standalone/configuration/logging.properties | grep logger.handlers
logger.handlers=ASYNC
$ docker run --rm -it registry.access.redhat.com/openshift3/metrics-hawkular-metrics:3.2.0 cat /opt/eap/standalone/configuration/logging.properties | grep logger.handlers
logger.handlers=ASYNC

Ah, that is the file after the server has been started. Before it starts it does have the ASYNC property in there. Not sure why exactly the logging.properties file is changed like this.

The logging subsystem "sync" the logging.properties with standalone.xml content during init phase. This is tricky Docker image specific issue only affects at first boot.

Bug fix haven't been included by current 3.1.0 images, will test after they were getting in

I believe this bug should be marked 3.1.1.  There is an updated 3.1.1 image, or for the whole 3.1 area, v3.1

Fixed in the below 3.1.1 images, able to get full log with "oc logs hawkular-metrics-xxxxx":
openshift3/metrics-hawkular-metrics    8f74a6934fe4
openshift3/metrics-heapster    c8b29234e903
openshift3/metrics-deployer    61e0a6767641
openshift3/metrics-cassandra    12d617a9aa1c

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-2016:1426