Log level 10 output is extremely verbose and co-mingles output from buildah sub-components. Is this still an issue if the log level is set to 4 or lower?

Reducing severity to low as this issue does not impact builds in normal use cases.

Log level 10 is _not_ important for reproducer. Sorry for adding it there and confused you. Of course mess gets into output with log level 4 or no log level. 
Parameter --timestamps=true is important for reproducing it. 

Setting severity to high to retriage it properly. During testing we are parsing build log. By default java client add --timestamps=true parameter (tracked elsewhere) so our testing cases relying on parsing log are broken currently. This have high severity for us.

oc logs --timestamps=true build/sti-1

2019-11-20T08:35:38.06583487Z [INFO] Downloaded from central: 2019-11-20T08:35:38.065911167Z https:2019-11-20T08:35:38.065975566Z /2019-11-20T08:35:38.06599902Z /2019-11-20T08:35:38.066043576Z r2019-11-20T08:35:38.066974399Z e2019-11-20T08:35:38.067038785Z p2019-11-20T08:35:38.0670624Z o2019-11-20T08:35:38.067095421Z 12019-11-20T08:35:38.067127518Z .2019-11-20T08:35:38.067145355Z m2019-11-20T08:35:38.067168616Z a2019-11-20T08:35:38.067207196Z v2019-11-20T08:35:38.067225069Z en2019-11-20T08:35:38.067239042Z .2019-11-20T08:35:38.067260033Z o2019-11-20T08:35:38.067337056Z rg2019-11-20T08:35:38.067419487Z /m2019-11-20T08:35:38.067442139Z a2019-11-20T08:35:38.067469453Z v2019-11-20T08:35:38.067499675Z e2019-11-20T08:35:38.067514642Z n2019-11-20T08:35:38.067528706Z 22019-11-20T08:35:38.067544151Z /2019-11-20T08:35:38.0675593Z o2019-11-20T08:35:38.067580501Z r2019-11-20T08:35:38.067594628Z g2019-11-20T08:35:38.067608628Z /2019-11-20T08:35:38.067625465Z co2019-11-20T08:35:38.067667073Z d2019-11-20T08:35:38.067682911Z eh2019-11-20T08:35:38.067697885Z a2019-11-20T08:35:38.067713059Z u2019-11-20T08:35:38.067742128Z s2019-11-20T08:35:38.067757069Z /p2019-11-20T08:35:38.067771094Z l2019-11-20T08:35:38.067786419Z e2019-11-20T08:35:38.067801622Z x2019-11-20T08:35:38.067823259Z u2019-11-20T08:35:38.06783712Z s2019-11-20T08:35:38.067850839Z /2019-11-20T08:35:38.067865906Z pl2019-11-20T08:35:38.067888716Z e2019-11-20T08:35:38.067904938Z x2019-11-20T08:35:38.06791829Z u2019-11-20T08:35:38.067932187Z s2019-11-20T08:35:38.067947165Z -2019-11-20T08:35:38.067962075Z i2019-11-20T08:35:38.067975346Z n2019-11-20T08:35:38.067996012Z t2019-11-20T08:35:38.068009548Z e2019-11-20T08:35:38.068024728Z rp2019-11-20T08:35:38.06804Z o2019-11-20T08:35:38.068055236Z l2019-11-20T08:35:38.068076195Z a2019-11-20T08:35:38.068089848Z t2019-11-20T08:35:38.068105781Z io2019-11-20T08:35:38.068121046Z n2019-11-20T08:35:38.068142193Z /2019-11-20T08:35:38.068181097Z 12019-11-20T08:35:38.068199777Z .12019-11-20T08:35:38.068213956Z 92019-11-20T08:35:38.068229467Z /2019-11-20T08:35:38.068250437Z p2019-11-20T08:35:38.06826683Z l2019-11-20T08:35:38.06828258Z ex2019-11-20T08:35:38.06829628Z u2019-11-20T08:35:38.068317046Z s2019-11-20T08:35:38.068334537Z -2019-11-20T08:35:38.068350302Z i2019-11-20T08:35:38.068366306Z nt2019-11-20T08:35:38.068381618Z e2019-11-20T08:35:38.068402976Z r2019-11-20T08:35:38.068417066Z p2019-11-20T08:35:38.068430161Z o2019-11-20T08:35:38.068445857Z l2019-11-20T08:35:38.06847387Z a2019-11-20T08:35:38.068492759Z ti2019-11-20T08:35:38.068506239Z o2019-11-20T08:35:38.068519245Z n2019-11-20T08:35:38.068533703Z -2019-11-20T08:35:38.068549065Z 12019-11-20T08:35:38.068565689Z .2019-11-20T08:35:38.068578867Z 12019-11-20T08:35:38.068591909Z 92019-11-20T08:35:38.068604972Z .2019-11-20T08:35:38.068620758Z p2019-11-20T08:35:38.06863536Z o2019-11-20T08:35:38.068650412Z m2019-11-20T08:35:38.06866335Z  2019-11-20T08:35:38.068676326Z (2019-11-20T08:35:38.068690373Z 12019-11-20T08:35:38.068705669Z .2019-11-20T08:35:38.068719726Z 02019-11-20T08:35:38.068732795Z  2019-11-20T08:35:38.068745791Z k2019-11-20T08:35:38.068758778Z B2019-11-20T08:35:38.068772718Z  2019-11-20T08:35:38.068788015Z a2019-11-20T08:35:38.068801765Z t2019-11-20T08:35:38.068816542Z  2019-11-20T08:35:38.068829489Z 22019-11-20T08:35:38.068842573Z 32019-11-20T08:35:38.068857902Z  k2019-11-20T08:35:38.068888669Z B2019-11-20T08:35:38.068903935Z /2019-11-20T08:35:38.068917151Z s2019-11-20T08:35:38.068931362Z )

The log for builds includes the following chain of standard outputs

{buildah build container stdout & stderr} -> buildah stdout -> openshift build stdout

This is pretty core behavior that we aren't going to change. The content from the output stream can vary wildly depending on the language and framework used in the build. 

Looking at the Github issue, the root cause is that _something_ in your call stack is asking for build logs with timestamps. I believe these timestamps are coming from Kubernetes itself, which we can't really control. Remove the request for timestamps and your output should be cleaner.

Let me formulate the problem here in detail. With new version of 4.2 we start to experience timestamps in logs randomly, we didn't see this behaviour in 4.1. Thus this is by definition regression for us.

Fact that timestamp shows randomly drop human readability of logs and breaks any tooling relying on parsing the logs. Such as in our case where we parse logs for specific patterns in tests.

Fact that java client request timestamps by default [1] is not the root cause it just reveals the bug.

So I expect some action will be taken here. 

> I believe these timestamps are coming from Kubernetes itself, which we can't really control
This is suprising for me. I mean, if you identify bug is in Kubernetes itself, don't we have ways to fix it? At least create issue for Kubernetes?

I was searching for Kubernetes issues regarding timestamps and find [2]. Seems to me it can be the same problem. Are you able to say which version of OCP will contain the fix [3]?

[1] https://github.com/fabric8io/kubernetes-client/issues/1850
[2] https://github.com/kubernetes/kubernetes/issues/77603
[3] https://github.com/kubernetes/kubernetes/pull/77822

@mchoma can you please provide an example of what the output looks like in 4.1? Are there timestamps in the log, but spaced in such a manner that the build log is easy to consume?

@adam.kaplan we dont currently have OCP 41 in our testing environment. It theoretically is possible I can try to create such, but it is not easy. How important this is? What do you expect from that. 

I have tried on OCP 4.2 with previous image and it is still fails so it is not about image in use.

As this test was not failing before than yes in 4.1 timestamps were not inserted inside log line massively like in case of 4.2 when --timestamps=true is used. 



Do you think it can be same problem as https://github.com/kubernetes/kubernetes/issues/77603 ?

@mchoma my team can try reproducing with a sample Wildfly S2I build. We can easily spin up any 4.x version of OpenShift.

Created attachment 1656397 [details]
s2i eap binary build - log level 10

Test buildConfig used in attempts to reproduce.

Created attachment 1656398 [details]
s2i binary build log - log level 10

@mchoma a few items:

1. `--loglevel=10` will maximize the logging on the client side, but will not alter the log level within the build itself. To increase the log level in a Binary build, add the `BUILD_LOGLEVEL` environment variable to the build strategy's `env` array [1].
2. I was unable to reproduce this issue on the latest 4.2 stable release (4.2.16) with maximum logging [2], nor was I able to reproduce on the 4.3.0 GA release. See my attached s2i-binary log, produced from the build-config-binary.yaml reproducer [3].

[1] https://docs.openshift.com/container-platform/4.2/builds/basic-build-operations.html#builds-basic-access-build-verbosity_basic-build-operations
[2] https://bugzilla.redhat.com/attachment.cgi?id=1656398
[3] https://bugzilla.redhat.com/attachment.cgi?id=1656397

I can still reproduce on 4.2.13. I am getting 4.2.16 to try this as well.

I am still able to reproduce on 4.2.16

15:25:26.519885515Z gin2020-01-30T15:25:26.519895615Z -repos2020-01-30T15:25:26.519905529Z itor2020-01-30T15:25:26.519915321Z y: fi2020-01-30T15:25:26.519925145Z le:/2020-01-30T15:25:26.519935047Z //opt/2020-01-30T15:25:26.519945057Z jbos2020-01-30T15:25:26.519955143Z s/cont2020-01-30T15:25:26.519965091Z aine2020-01-30T15:25:26.519975048Z r/wild2020-01-30T15:25:26.519985121Z fly/s2020-01-30T15:25:26.519995149Z 2i/g2020-01-30T15:25:26.520005417Z alleon2020-01-30T15:25:26.520015429Z /galle2020-01-30T15:25:26.520025604Z on-2020-01-30T15:25:26.520035569Z m2-rep2020-01-30T15:25:26.520045599Z ositor2020-01-30T15:25:26.520055847Z y/or2020-01-30T15:25:26.520066027Z g/apac2020-01-30T15:25:26.520076008Z he/2020-01-30T15:25:26.520086101Z maven/2020-01-30T15:25:26.520096262Z maven-2020-01-30T15:25:26.520106251Z repo2020-01-30T15:25:26.520116195Z sito2020-01-30T15:25:26.520126165Z ry-met2020-01-30T15:25:26.520136081Z adat2020-01-30T15:25:26.520149929Z a/2.0.92020-01-30T15:25:26.520168229Z /maven-rep2020-01-30T15:25:26.520185259Z ository-2020-01-30T15:25:26.520200539Z metadata2020-01-30T15:25:26.520211541Z

We test on OpenStack and AWS, both installed with installer and used method is IPI. 

Sorry, cot sure about RHCOS question? How can I find out? Does it answer that we use openshift IPI installer?

Do you see https://github.com/kubernetes/kubernetes/issues/77603 related to this bugzilla?

Reproduced on 4.4.0. The overlapping timestamps aren't as bad on 4.4 as they are on 4.3 and 4.2, but they are still present during the Maven artifact download. I don't see this behavior in the logs produced by buildah itself or the source clone operation.

Created attachment 1662263 [details]
eap builld - no timestamps

Created attachment 1662264 [details]
eap build w/ timestamps

Note extra timestamps written during maven downloads.

The current problem in 4.4 isn't that bad, namely you'll notice following lines:

2020-02-10T17:58:43.28595137Z [IN2020-02-10T17:58:43.286101121Z FO]2020-02-10T17:58:43.286152445Z  Err2020-02-10T17:58:43.286191126Z or 2020-02-10T17:58:43.287949624Z stacktraces are turned on.

from time to time, with this I think we can think about addressing this issue upstream first.

This is working perfectly fine with latest oc version, see below:

2020-05-11T11:44:14.333320496Z time="2020-05-11T11:44:14Z" level=debug msg="Looking for TLS certificates and private keys in /etc/docker/certs.d/image-registry.openshift-image-registry.svc:5000"
2020-05-11T11:44:14.333369927Z time="2020-05-11T11:44:14Z" level=debug msg=" crt: /etc/docker/certs.d/image-registry.openshift-image-registry.svc:5000/ca.crt"
2020-05-11T11:44:14.35358894Z time="2020-05-11T11:44:14Z" level=debug msg="GET https://image-registry.openshift-image-registry.svc:5000/v2/"
2020-05-11T11:44:14.365888922Z time="2020-05-11T11:44:14Z" level=debug msg="Ping https://image-registry.openshift-image-registry.svc:5000/v2/ status 401"
2020-05-11T11:44:14.366021801Z time="2020-05-11T11:44:14Z" level=debug msg="GET https://image-registry.openshift-image-registry.svc:5000/openshift/token?account=serviceaccount&scope=repository%3Aopenshift%2Fjboss-eap72-openshift%3Apull"
2020-05-11T11:44:14.383901265Z time="2020-05-11T11:44:14Z" level=debug msg="Increasing token expiration to: 60 seconds"
2020-05-11T11:44:14.383931683Z time="2020-05-11T11:44:14Z" level=debug msg="GET https://image-registry.openshift-image-registry.svc:5000/v2/openshift/jboss-eap72-openshift/manifests/sha256:0ccdd318a10c4fe9e1baaff43f9523ecd696f048cf29059a7cea3b88d99109c9"
2020-05-11T11:44:14.437840745Z time="2020-05-11T11:44:14Z" level=debug msg="Using blob info cache at /var/lib/containers/storage/cache/blob-info-cache-v1.boltdb"
2020-05-11T11:44:14.437925252Z time="2020-05-11T11:44:14Z" level=debug msg="IsRunningImageAllowed for image docker:image-registry.openshift-image-registry.svc:5000/openshift/jboss-eap72-openshift@sha256:0ccdd318a10c4fe9e1baaff43f9523ecd696f048cf29059a7cea3b88d99109c9"
2020-05-11T11:44:14.437925252Z time="2020-05-11T11:44:14Z" level=debug msg=" Using default policy section"
2020-05-11T11:44:14.437937772Z time="2020-05-11T11:44:14Z" level=debug msg=" Requirement 0: allowed"
2020-05-11T11:44:14.437937772Z time="2020-05-11T11:44:14Z" level=debug msg="Overall: allowed"

I'm moving this to qa for verification.

[root@dhcp-140-138 infrastructure]# oc version -o yaml
clientVersion:
  buildDate: "2020-05-07T22:03:52Z"
  compiler: gc
  gitCommit: f415627b3a8df305c4dd0ada0b4bc1271846a777
  gitTreeState: clean
  gitVersion: 4.5.0-202005072157-f415627
  goVersion: go1.13.4
  major: ""
  minor: ""
  platform: linux/amd64


[root@dhcp-140-138 infrastructure]# oc logs --timestamps=true build/ruby-ex-2  --loglevel=10
I0512 10:28:29.117848   28831 loader.go:375] Config loaded from file:  /root/kubeconfig
I0512 10:28:29.119149   28831 cached_discovery.go:114] returning cached discovery info from /root/.kube/cache/discovery/api.yinzhou11.qe.devcluster.openshift.com_6443/servergroups.json
I0512 10:28:29.119703   28831 cached_discovery.go:71] returning cached discovery info from /root/.kube/cache/discovery/api.yinzhou11.qe.devcluster.openshift.com_6443/metrics.k8s.io/v1beta1/serverresources.json
I0512 10:28:29.119745   28831 cached_discovery.go:71] returning cached discovery info from /root/.kube/cache/discovery/api.yinzhou11.qe.devcluster.openshift.com_6443/authentication.k8s.io/v1beta1/serverresources.json
I0512 10:28:29.119754   28831 cached_discovery.go:71] returning cached discovery info from /root/.kube/cache/discovery/api.yinzhou11.qe.devcluster.openshift.com_6443/certificates.k8s.io/v1beta1/serverresources.json
I0512 10:28:29.119818   28831 cached_discovery.go:71] returning cached discovery info from /root/.kube/cache/discovery/api.yinzhou11.qe.devcluster.openshift.com_6443/oauth.openshift.io/v1/serverresources.json

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-2020:2409