search

fabric8io / kubernetes-client

Java client for Kubernetes & OpenShift
http://fabric8.io
Apache License 2.0
3.41k stars 1.46k forks source link

Build log is populated by timestamps #1850

Closed mchoma closed 4 years ago

mchoma commented 4 years ago

After upgrading openshift client we start to experience on OpenShift 4 that timestamps are injected also into middle of line, which breaks looking for specific pattern

Log in openshift console:

[INFO] BUILD FAILURE

Log in test:

2019-10-31T19:47:58.096107367Z [IN2019-10-31T19:47:58.096124533Z FO] BUIL2019-10-31T19:47:58.096141464Z D FAIL2019-10-31T19:47:58.09615766Z URE

I believe it has something to do with https://github.com/fabric8io/kubernetes-client/issues/579. How can we turn off this behaviour?

This is how we get log

    public String getBuildLog(Build build) {
        return builds().withName(build.getMetadata().getName()).getLog();
    }
mchoma commented 4 years ago

@rohanKanojia @pmcq FYI

rohanKanojia commented 4 years ago

ah, this doesn't look good. Let me try to fix this as soon as possible.

rohanKanojia commented 4 years ago

@mchoma : Could you please share your build object if possible? I tried reproducing your issue but could not.

I tried with this build object:

~/go/src/github.com/fabric8io/kubernetes-client : $ oc get build
NAME                      TYPE      FROM      STATUS     STARTED        DURATION
random-generator-s2i-1    Source    Binary    Complete   25 hours ago   37s
random-generator-s2i-2    Docker    Binary    Complete   25 hours ago   1m30s
spring-boot-camel-s2i-1   Source    Binary    Complete   3 hours ago    43s
~/go/src/github.com/fabric8io/kubernetes-client : $ oc logs build/spring-boot-camel-s2i-1
Receiving source from STDIN as archive ...
Using fabric8/s2i-java:2.1 as the s2i builder image
==================================================================
Starting S2I Java Build .....
S2I binary build from fabric8-maven-plugin detected
Copying binaries from /tmp/src/maven to /deployments ...
Checking for SpringBoot archive...
Found spring-boot-camel-1.0-SNAPSHOT.jar...
... done

Pushing image 172.30.39.149:5000/rokumar/spring-boot-camel:latest ...
Pushed 0/26 layers, 0% complete
Pushed 1/26 layers, 4% complete
Pushed 2/26 layers, 11% complete
Pushed 3/26 layers, 14% complete
Pushed 4/26 layers, 17% complete
Pushed 5/26 layers, 20% complete
Pushed 6/26 layers, 31% complete
Pushed 7/26 layers, 33% complete
Pushed 8/26 layers, 35% complete
Pushed 9/26 layers, 42% complete
Pushed 10/26 layers, 47% complete
Pushed 11/26 layers, 48% complete
Pushed 12/26 layers, 53% complete
Pushed 13/26 layers, 58% complete
Pushed 14/26 layers, 62% complete
Pushed 15/26 layers, 62% complete
Pushed 16/26 layers, 62% complete
Push successful

But when I ran this code in my IDE:

    try {
      OpenShiftClient client = new DefaultOpenShiftClient();
      logger.info(client.builds().inNamespace("rokumar").withName("spring-boot-camel-s2i-1").getLog());
    } catch (KubernetesClientException e) {
      logger.error(e.getMessage(), e);
    }

resulting output was like this:

/usr/local/jdk-11.0.2/bin/java -javaagent:/opt/idea-IC-191.7479.19/lib/idea_rt.jar=42041:/opt/idea-IC-191.7479.19/bin -Dfile.encoding=UTF-8 -classpath /home/rohaan/go/src/github.com/fabric8io/kubernetes-client/kubernetes-examples/target/classes:/home/rohaan/go/src/github.com/fabric8io/kubernetes-client/openshift-client/target/classes:/home/rohaan/go/src/github.com/fabric8io/kubernetes-client/kubernetes-client/target/classes:/home/rohaan/.m2/repository/io/fabric8/kubernetes-model/4.7-SNAPSHOT/kubernetes-model-4.7-SNAPSHOT.jar:/home/rohaan/.m2/repository/io/fabric8/kubernetes-model-common/4.7-SNAPSHOT/kubernetes-model-common-4.7-SNAPSHOT.jar:/home/rohaan/.m2/repository/com/fasterxml/jackson/module/jackson-module-jaxb-annotations/2.9.10/jackson-module-jaxb-annotations-2.9.10.jar:/home/rohaan/.m2/repository/com/squareup/okhttp3/okhttp/3.12.6/okhttp-3.12.6.jar:/home/rohaan/.m2/repository/com/squareup/okio/okio/1.15.0/okio-1.15.0.jar:/home/rohaan/.m2/repository/com/squareup/okhttp3/logging-interceptor/3.12.6/logging-interceptor-3.12.6.jar:/home/rohaan/.m2/repository/com/fasterxml/jackson/dataformat/jackson-dataformat-yaml/2.9.10/jackson-dataformat-yaml-2.9.10.jar:/home/rohaan/.m2/repository/org/yaml/snakeyaml/1.23/snakeyaml-1.23.jar:/home/rohaan/.m2/repository/com/fasterxml/jackson/core/jackson-databind/2.9.10/jackson-databind-2.9.10.jar:/home/rohaan/.m2/repository/com/fasterxml/jackson/core/jackson-annotations/2.9.10/jackson-annotations-2.9.10.jar:/home/rohaan/.m2/repository/com/fasterxml/jackson/core/jackson-core/2.9.10/jackson-core-2.9.10.jar:/home/rohaan/.m2/repository/io/fabric8/zjsonpatch/0.3.0/zjsonpatch-0.3.0.jar:/home/rohaan/.m2/repository/com/github/mifmif/generex/1.0.2/generex-1.0.2.jar:/home/rohaan/.m2/repository/dk/brics/automaton/automaton/1.11-8/automaton-1.11-8.jar:/home/rohaan/.m2/repository/org/slf4j/slf4j-simple/1.7.29/slf4j-simple-1.7.29.jar:/home/rohaan/.m2/repository/org/slf4j/slf4j-api/1.7.29/slf4j-api-1.7.29.jar:/home/rohaan/.m2/repository/org/junit/jupiter/junit-jupiter-engine/5.5.2/junit-jupiter-engine-5.5.2.jar:/home/rohaan/.m2/repository/org/apiguardian/apiguardian-api/1.1.0/apiguardian-api-1.1.0.jar:/home/rohaan/.m2/repository/org/junit/platform/junit-platform-engine/1.5.2/junit-platform-engine-1.5.2.jar:/home/rohaan/.m2/repository/org/opentest4j/opentest4j/1.2.0/opentest4j-1.2.0.jar:/home/rohaan/.m2/repository/org/junit/platform/junit-platform-commons/1.5.2/junit-platform-commons-1.5.2.jar:/home/rohaan/.m2/repository/org/junit/jupiter/junit-jupiter-api/5.5.2/junit-jupiter-api-5.5.2.jar:/home/rohaan/.m2/repository/org/junit/jupiter/junit-jupiter-migrationsupport/5.5.2/junit-jupiter-migrationsupport-5.5.2.jar:/home/rohaan/.m2/repository/junit/junit/4.12/junit-4.12.jar:/home/rohaan/.m2/repository/org/hamcrest/hamcrest-core/1.3/hamcrest-core-1.3.jar io.fabric8.kubernetes.examples.DeleteExamples
[main] INFO io.fabric8.kubernetes.examples.DeleteExamples - 2019-11-05T12:39:47.200683757Z Receiving source from STDIN as archive ...
2019-11-05T12:39:57.349826046Z Using fabric8/s2i-java:2.1 as the s2i builder image
2019-11-05T12:39:58.22681253Z ==================================================================
2019-11-05T12:39:58.226833072Z Starting S2I Java Build .....
2019-11-05T12:39:58.226838989Z S2I binary build from fabric8-maven-plugin detected
2019-11-05T12:39:58.226843891Z Copying binaries from /tmp/src/maven to /deployments ...
2019-11-05T12:39:58.257843872Z Checking for SpringBoot archive...
2019-11-05T12:39:58.274575827Z Found spring-boot-camel-1.0-SNAPSHOT.jar...
2019-11-05T12:39:58.293472795Z ... done
2019-11-05T12:40:00.582968271Z 
2019-11-05T12:40:00.582987591Z Pushing image 172.30.39.149:5000/rokumar/spring-boot-camel:latest ...
2019-11-05T12:40:15.992739274Z Pushed 0/26 layers, 0% complete
2019-11-05T12:40:16.382164237Z Pushed 1/26 layers, 4% complete
2019-11-05T12:40:17.745281063Z Pushed 2/26 layers, 11% complete
2019-11-05T12:40:17.787173773Z Pushed 3/26 layers, 14% complete
2019-11-05T12:40:17.887718644Z Pushed 4/26 layers, 17% complete
2019-11-05T12:40:18.002864506Z Pushed 5/26 layers, 20% complete
2019-11-05T12:40:18.896337422Z Pushed 6/26 layers, 31% complete
2019-11-05T12:40:19.020132641Z Pushed 7/26 layers, 33% complete
2019-11-05T12:40:19.046042688Z Pushed 8/26 layers, 35% complete
2019-11-05T12:40:19.504209834Z Pushed 9/26 layers, 42% complete
2019-11-05T12:40:19.92673835Z Pushed 10/26 layers, 47% complete
2019-11-05T12:40:19.964440083Z Pushed 11/26 layers, 48% complete
2019-11-05T12:40:20.702986587Z Pushed 12/26 layers, 53% complete
2019-11-05T12:40:21.404372283Z Pushed 13/26 layers, 58% complete
2019-11-05T12:40:21.808154149Z Pushed 14/26 layers, 62% complete
2019-11-05T12:40:22.556683845Z Pushed 15/26 layers, 62% complete
2019-11-05T12:40:23.66592306Z Pushed 16/26 layers, 62% complete
2019-11-05T12:40:25.877822822Z Push successful
mchoma commented 4 years ago

Strange. I can't reproduce locally now. Let me try again in lab where we hit this issue originally...

Edit: It seems intermittent. 2x NOK, 2x OK locally. Can you try your reproducer several times?

Edit: It is intermittent because timestamps are generated randomly. Sometimes matching pattern was not corrupted

mchoma commented 4 years ago

I am able to reproduce with 

kind: BuildConfig
apiVersion: build.openshift.io/v1
metadata:
  name: helloworld-html5-build-artifacts
  namespace: mchoma
  labels:
    application: helloworld-html5
    template: eap-cd-basic-s2i
    xpaas: '17.0'
spec:
  output:
    to:
      kind: ImageStreamTag
      name: 'helloworld-html5-build-artifacts:latest'
  strategy:
    type: Source
    sourceStrategy:
      from:
        kind: ImageStreamTag
        namespace: mchoma
        name: 'eap-cd-openshift:17'
      env:
        - name: MAVEN_ARGS_APPEND
          value: '-Dcom.redhat.xpaas.repo.jbossorg'
        - name: GALLEON_PROVISION_LAYERS
          value: jaxrs-server
        - name: GALLEON_PROVISION_DEFAULT_FAT_SERVER
          value: 'true'
        - name: ARTIFACT_DIR
  source:
    type: Git
    git:
      uri: 'https://github.com/jboss-developer/jboss-eap-quickstarts.git'
      ref: openshift
    contextDir: helloworld-html5
  runPolicy: Serial
status:
  lastVersion: 1

and 

public class BuildLogTest {

    protected static final OpenShift openShift = OpenShifts.master();

    @Test
    public void buildLogTest() throws IOException {
        OpenShiftConfig openShiftConfig = ((OpenShiftConfigBuilder)((OpenShiftConfigBuilder)((OpenShiftConfigBuilder)((OpenShiftConfigBuilder)((OpenShiftConfigBuilder)(new OpenShiftConfigBuilder()).withMasterUrl("https://192.168.130.11:6443/")).withTrustCerts(true)).withNamespace("mchoma")).withUsername("admin")).withPassword("admin")).build();
        OpenShiftClient client = new DefaultOpenShiftClient(openShiftConfig);
        System.out.println(client.builds().inNamespace("mchoma").withName("helloworld-html5-build-artifacts2-2").getLog());
    }

}

Note, I wasnt able to reproduce with ruby s2i. So maybe it is dependent on builder image? Is it possible timestamp "hook" to some hidden whitespace???

mchoma commented 4 years ago

So I think problem of client is why with this code 

        OpenShiftConfig openShiftConfig = ((OpenShiftConfigBuilder)((OpenShiftConfigBuilder)((OpenShiftConfigBuilder)((OpenShiftConfigBuilder)((OpenShiftConfigBuilder)(new OpenShiftConfigBuilder()).withMasterUrl("https://192.168.130.11:6443/")).withTrustCerts(true)).withNamespace("mchoma")).withUsername("admin")).withPassword("admin")).build();
        OpenShiftClient client = new DefaultOpenShiftClient(openShiftConfig);
        System.out.println(client.builds().inNamespace("mchoma").withName("sti-2").getLog());

I see this url beeing called https://192.168.130.11:6443/apis/build.openshift.io/v1/namespaces/mchoma/builds/sti-2/log?pretty=false&timestamps=true How can I get rid of &timestamps=true beeing appended?

It means I am not calling .usingTimestamp() and still seeing &timestamps=true among parameters

mchoma commented 4 years ago

I see random timestamps also with oc command

oc logs --timestamps=true build/sti-2 --loglevel=10

it means

curl -k -v -XGET -H "Accept: application/json, */*" -H "User-Agent: oc/v1.13.4+41ca470 (linux/amd64) kubernetes/41ca470" -H "Authorization: Bearer AxLQ4UAdLLuiw5t3nHDirsaA2SYvKMbyG0TyPJV4Wjs" 'https://192.168.130.11:6443/apis/build.openshift.io/v1/namespaces/mchoma/builds/sti-2/log?timestamps=true'

I am going to submit issue for that into openshift. But from openshift-client I would expect to have a way to get logs without timestamp.

Edit: Openshift bug: https://bugzilla.redhat.com/show_bug.cgi?id=1769798

mchoma commented 4 years ago

@rohanKanojia So I believe problem here remains openshift client always request for timestamp no matter if .usingTimestamp() is used or not.

Is this just about setting somewhere default timestamps=false properly? Could you have look?

With this bug in place and Kubernetes bug when timestamps=true [1] We cant solve our use case properly.

[1] https://github.com/kubernetes/kubernetes/issues/77603

rohanKanojia commented 4 years ago

@mchoma : I checked and I also couldn't find any option for setting timestamps=false . let me add an option to disable this.

rohanKanojia commented 4 years ago

@mchoma : I've created a PR to add an option withoutUsingTimestamps() to enable timestamps=false. Would it be able to help your use case?

mchoma commented 4 years ago

@rohanKanojia yes I hope so.