search

apache / openwhisk-deploy-kube

The Apache OpenWhisk Kubernetes Deployment repository supports deploying the Apache OpenWhisk system on Kubernetes and OpenShift clusters.
https://openwhisk.apache.org/
Apache License 2.0
301 stars 231 forks source link

Helm installation stuck on install package #531

Closed zyqCSL closed 5 years ago

zyqCSL commented 5 years ago

There is one invoker in the system, but helm installation still gets stuck on install-packages:

Labels:             beta.kubernetes.io/arch=amd64
                    beta.kubernetes.io/os=linux
                    kubernetes.io/arch=amd64
                    kubernetes.io/hostname=ath-9
                    kubernetes.io/os=linux
                    openwhisk-role=invoker

Helm status output as follows:

NAMESPACE: openwhisk
STATUS: DEPLOYED

RESOURCES:
==> v1/ConfigMap
NAME                         DATA  AGE
owdev-db.config              10    9m19s
owdev-init-couchdb           1     9m19s
owdev-install-packages-cm    1     9m19s
owdev-invoker-scripts        2     9m19s
owdev-nginx                  1     9m19s
owdev-tests-package-checker  1     9m19s
owdev-tests-smoketest        1     9m19s
owdev-whisk.config           9     9m19s
owdev-zookeeper              1     9m19s

==> v1/DaemonSet
NAME           DESIRED  CURRENT  READY  UP-TO-DATE  AVAILABLE  NODE SELECTOR  AGE
owdev-invoker  1        1        1      1           1          <none>         9m18s

==> v1/Deployment
NAME                    READY  UP-TO-DATE  AVAILABLE  AGE
owdev-alarmprovider     1/1    1           1          9m18s
owdev-apigateway        1/1    1           1          9m18s
owdev-cloudantprovider  1/1    1           1          9m18s
owdev-couchdb           1/1    1           1          9m18s
owdev-kafkaprovider     1/1    1           1          9m18s
owdev-nginx             1/1    1           1          9m18s
owdev-redis             1/1    1           1          9m18s

==> v1/Job
NAME                    COMPLETIONS  DURATION  AGE
owdev-init-couchdb      1/1          54s       9m18s
owdev-install-packages  0/1          9m18s     9m18s

==> v1/Pod
NAME            READY  STATUS   RESTARTS  AGE
owdev-wskadmin  1/1    Running  0         9m18s

==> v1/Pod(related)
NAME                                    READY  STATUS     RESTARTS  AGE
owdev-alarmprovider-6d88cf7bdd-dbq7c    1/1    Running    0         9m18s
owdev-apigateway-7bc6f5df6d-pwqjm       1/1    Running    0         9m18s
owdev-cloudantprovider-bc8bfc9bf-55g87  1/1    Running    0         9m18s
owdev-controller-0                      1/1    Running    0         9m18s
owdev-couchdb-7c89c7b77-wg4m2           1/1    Running    0         9m18s
owdev-init-couchdb-mxs5h                0/1    Completed  0         9m18s
owdev-install-packages-b62nt            0/1    Init:0/1   0         9m18s
owdev-invoker-7899q                     1/1    Running    0         9m18s
owdev-kafka-0                           1/1    Running    0         9m18s
owdev-kafkaprovider-68d8b47b74-49sfg    1/1    Running    0         9m18s
owdev-nginx-5479b9ff5f-t4v7z            1/1    Running    0         9m18s
owdev-redis-58d7ff9bbf-9hkcq            1/1    Running    0         9m18s
owdev-zookeeper-0                       1/1    Running    0         9m18s

==> v1/RoleBinding
NAME              AGE
owdev-allow-view  9m19s

==> v1/Secret
NAME                        TYPE    DATA  AGE
owdev-db.auth               Opaque  2     9m19s
owdev-docker.registry.auth  Opaque  2     9m19s
owdev-nginx                 tls     2     9m19s
owdev-whisk.auth            Opaque  2     9m19s

==> v1/Service
NAME              TYPE       CLUSTER-IP      EXTERNAL-IP  PORT(S)                     AGE
owdev-apigateway  ClusterIP  10.100.148.174  <none>       8080/TCP,9000/TCP           9m19s
owdev-controller  ClusterIP  10.108.246.137  <none>       8080/TCP                    9m19s
owdev-couchdb     ClusterIP  10.98.0.123     <none>       5984/TCP                    9m19s
owdev-kafka       ClusterIP  None            <none>       9092/TCP                    9m19s
owdev-nginx       NodePort   10.99.45.251    <none>       80:31509/TCP,443:31001/TCP  9m19s
owdev-redis       ClusterIP  10.109.224.197  <none>       6379/TCP                    9m18s
owdev-zookeeper   ClusterIP  None            <none>       2181/TCP,2888/TCP,3888/TCP  9m18s

==> v1/ServiceAccount
NAME        SECRETS  AGE
owdev-core  1        9m19s

==> v1/StatefulSet
NAME              READY  AGE
owdev-controller  1/1    9m18s
owdev-kafka       1/1    9m18s
owdev-zookeeper   1/1    9m18s
chetanmeh commented 5 years ago

Based on 

owdev-install-packages-b62nt            0/1    Init:0/1   0         9m18s

It looks like the init container is still waiting which per impl

https://github.com/apache/openwhisk-deploy-kube/blob/32c71d68ec57b922475be1c6174e23682cfa2277/helm/openwhisk/templates/install-packages-job.yaml#L39-L42

Is waiting for healthy invokers. Can you check invoker logs to see if its able to work properly and able to send health pings

zyqCSL commented 5 years ago

Many thanks for the prompt reply!

The invoker log looks fine to me:

[2019-09-26T05:10:31.515Z] [INFO] Started the Kamon StatsD reporter
[2019-09-26T05:10:31.518Z] [INFO] Loaded metric reporter [kamon.statsd.StatsDReporter]
[2019-09-26T05:10:32.170Z] [INFO] Slf4jLogger started
[2019-09-26T05:10:32.733Z] [INFO] [#tid_sid_unknown] [Config] environment set value for whisk.api.host.name
[2019-09-26T05:10:32.735Z] [INFO] [#tid_sid_unknown] [Config] environment set value for whisk.api.host.proto
[2019-09-26T05:10:32.735Z] [INFO] [#tid_sid_unknown] [Config] environment set value for whisk.api.host.port
[2019-09-26T05:10:32.736Z] [INFO] [#tid_sid_unknown] [Config] environment set value for zookeeper.hosts
[2019-09-26T05:10:32.736Z] [INFO] [#tid_sid_unknown] [Config] environment set value for runtimes.manifest
[2019-09-26T05:10:32.737Z] [INFO] [#tid_sid_unknown] [Config] environment set value for kafka.hosts
[2019-09-26T05:10:32.738Z] [INFO] [#tid_sid_unknown] [Config] environment set value for port
[2019-09-26T05:10:33.210Z] [INFO] [#tid_sid_unknown] [Invoker] Command line arguments parsed to yield CmdLineArgs(Some(ath-9),None,None)
[2019-09-26T05:10:33.212Z] [INFO] [#tid_sid_unknown] [InstanceIdAssigner] invokerReg: creating zkClient to owdev-zookeeper-0.owdev-zookeeper.openwhisk.svc.cluster.local:2181
[2019-09-26T05:10:33.263Z] [INFO] Running in ZooKeeper 3.4.x compatibility mode
[2019-09-26T05:10:33.282Z] [INFO] Starting
[2019-09-26T05:10:33.297Z] [INFO] Client environment:zookeeper.version=3.4.11-37e277162d567b55a07d1755f0b31c32e93c01a0, built on 11/01/2017 18:06 GMT
[2019-09-26T05:10:33.297Z] [INFO] Client environment:host.name=owdev-invoker-svhm8
[2019-09-26T05:10:33.297Z] [INFO] Client environment:java.version=1.8.0-adoptopenjdk
[2019-09-26T05:10:33.297Z] [INFO] Client environment:java.vendor=Oracle Corporation
[2019-09-26T05:10:33.297Z] [INFO] Client environment:java.home=/opt/java/openjdk/jre
[2019-09-26T05:10:33.297Z] [INFO] Client environment:java.class.path=/invoker/classes:/invoker/lib/openwhisk-invoker-1.0.0-SNAPSHOT.jar:/invoker/lib/openwhisk-common-1.0.0-SNAPSHOT.jar:/invoker/lib/pureconfig_2.12-0.9.0.jar:/invoker/lib/mesos-actor-0.0.17.jar:/invoker/lib/akka-management-cluster-bootstrap_2.12-0.10.0.jar:/invoker/lib/akka-discovery-marathon-api_2.12-0.10.0.jar:/invoker/lib/akka-management_2.12-0.10.0.jar:/invoker/lib/akka-http-spray-json_2.12-10.1.8.jar:/invoker/lib/spray-json_2.12-1.3.5.jar:/invoker/lib/fastparse_2.12-1.0.0.jar:/invoker/lib/akka-stream-alpakka-file_2.12-0.15.jar:/invoker/lib/akka-stream-alpakka-s3_2.12-1.0.1.jar:/invoker/lib/akka-stream-alpakka-simple-codecs_2.12-0.9.jar:/invoker/lib/akka-cluster-metrics_2.12-2.5.22.jar:/invoker/lib/akka-cluster-tools_2.12-2.5.22.jar:/invoker/lib/akka-distributed-data_2.12-2.5.22.jar:/invoker/lib/akka-cluster_2.12-2.5.22.jar:/invoker/lib/akka-remote_2.12-2.5.22.jar:/invoker/lib/akka-stream_2.12-2.5.22.jar:/invoker/lib/akka-slf4j_2.12-2.5.22.jar:/invoker/lib/akka-discovery_2.12-0.10.0.jar:/invoker/lib/akka-coordination_2.12-2.5.22.jar:/invoker/lib/akka-actor_2.12-2.5.22.jar:/invoker/lib/akka-http-xml_2.12-10.1.8.jar:/invoker/lib/akka-http_2.12-10.1.8.jar:/invoker/lib/akka-http-core_2.12-10.1.8.jar:/invoker/lib/kamon-statsd_2.12-1.0.0.jar:/invoker/lib/kamon-system-metrics_2.12-1.0.0.jar:/invoker/lib/kamon-prometheus_2.12-1.1.1.jar:/invoker/lib/kamon-datadog_2.12-1.0.0.jar:/invoker/lib/rxscala_2.12-0.26.5.jar:/invoker/lib/pureconfig-macros_2.12-0.9.0.jar:/invoker/lib/shapeless_2.12-2.3.2.jar:/invoker/lib/fastparse-utils_2.12-1.0.0.jar:/invoker/lib/kamon-core_2.12-1.1.3.jar:/invoker/lib/fansi_2.12-0.2.4.jar:/invoker/lib/sourcecode_2.12-0.1.4.jar:/invoker/lib/scala-java8-compat_2.12-0.8.0.jar:/invoker/lib/akka-protobuf_2.12-2.5.22.jar:/invoker/lib/ssl-config-core_2.12-0.3.7.jar:/invoker/lib/akka-parsing_2.12-10.1.8.jar:/invoker/lib/macro-compat_2.12-1.1.1.jar:/invoker/lib/scala-parser-combinators_2.12-1.1.1.jar:/invoker/lib/scala-xml_2.12-1.1.1.jar:/invoker/lib/scala-library-2.12.9.jar:/invoker/lib/curator-recipes-4.0.0.jar:/invoker/lib/zookeeper-3.4.11.jar:/invoker/lib/logback-classic-1.2.3.jar:/invoker/lib/jcl-over-slf4j-1.7.25.jar:/invoker/lib/log4j-over-slf4j-1.7.25.jar:/invoker/lib/aws-java-sdk-cloudfront-1.11.517.jar:/invoker/lib/aws-java-sdk-core-1.11.517.jar:/invoker/lib/httpclient-4.5.5.jar:/invoker/lib/commons-codec-1.10.jar:/invoker/lib/azure-cosmosdb-2.4.2.jar:/invoker/lib/azure-cosmosdb-direct-2.4.2.jar:/invoker/lib/azure-cosmosdb-gateway-2.4.2.jar:/invoker/lib/azure-cosmosdb-commons-2.4.2.jar:/invoker/lib/commons-io-2.6.jar:/invoker/lib/commons-validator-1.6.jar:/invoker/lib/commons-beanutils-1.9.2.jar:/invoker/lib/commons-collections-3.2.2.jar:/invoker/lib/kafka-clients-2.0.0.jar:/invoker/lib/java-uuid-generator-3.1.4.jar:/invoker/lib/caffeine-2.6.2.jar:/invoker/lib/protobuf-java-util-3.3.1.jar:/invoker/lib/curator-framework-4.0.0.jar:/invoker/lib/curator-client-4.0.0.jar:/invoker/lib/guava-27.0.1-jre.jar:/invoker/lib/jsr305-3.0.2.jar:/invoker/lib/kubernetes-client-4.4.2.jar:/invoker/lib/opentracing-util-0.31.0.jar:/invoker/lib/brave-opentracing-0.31.0.jar:/invoker/lib/opentracing-noop-0.31.0.jar:/invoker/lib/opentracing-api-0.31.0.jar:/invoker/lib/zipkin-sender-okhttp3-2.6.1.jar:/invoker/lib/brave-5.0.0.jar:/invoker/lib/zipkin-reporter-2.6.1.jar:/invoker/lib/rxjava-reactive-streams-1.2.1.jar:/invoker/lib/audience-annotations-0.5.0.jar:/invoker/lib/netty-3.10.6.Final.jar:/invoker/lib/config-1.3.3.jar:/invoker/lib/reactive-streams-1.0.2.jar:/invoker/lib/jul-to-slf4j-1.7.26.jar:/invoker/lib/rxnetty-0.4.20.jar:/invoker/lib/slf4j-api-1.7.26.jar:/invoker/lib/logback-core-1.2.3.jar:/invoker/lib/lz4-java-1.4.1.jar:/invoker/lib/snappy-java-1.1.7.1.jar:/invoker/lib/httpcore-4.4.9.jar:/invoker/lib/kubernetes-model-4.4.2.jar:/invoker/lib/logging-interceptor-3.12.0.jar:/invoker/lib/okhttp-3.12.0.jar:/invoker/lib/jackson-dataformat-yaml-2.9.9.jar:/invoker/lib/zjsonpatch-0.3.0.jar:/invoker/lib/jmespath-java-1.11.517.jar:/invoker/lib/jackson-module-jaxb-annotations-2.9.9.jar:/invoker/lib/jackson-databind-2.9.9.3.jar:/invoker/lib/jackson-dataformat-cbor-2.6.7.jar:/invoker/lib/jackson-core-2.9.9.jar:/invoker/lib/generex-1.0.2.jar:/invoker/lib/HdrHistogram-2.1.9.jar:/invoker/lib/nanohttpd-2.3.1.jar:/invoker/lib/mesos-1.2.3.jar:/invoker/lib/zipkin-2.8.4.jar:/invoker/lib/rxjava-extras-0.8.0.17.jar:/invoker/lib/rxjava-string-1.1.1.jar:/invoker/lib/rxjava-1.3.8.jar:/invoker/lib/netty-handler-proxy-4.1.32.Final.jar:/invoker/lib/netty-codec-http-4.1.32.Final.jar:/invoker/lib/netty-handler-4.1.32.Final.jar:/invoker/lib/netty-codec-socks-4.1.32.Final.jar:/invoker/lib/netty-codec-4.1.32.Final.jar:/invoker/lib/netty-transport-4.1.32.Final.jar:/invoker/lib/commons-text-1.6.jar:/invoker/lib/commons-lang3-3.8.1.jar:/invoker/lib/kubernetes-model-common-4.4.2.jar:/invoker/lib/validation-api-2.0.1.Final.jar:/invoker/lib/javax.el-3.0.1-b11.jar:/invoker/lib/okio-1.15.0.jar:/invoker/lib/snakeyaml-1.23.jar:/invoker/lib/jackson-annotations-2.9.0.jar:/invoker/lib/automaton-1.11-8.jar:/invoker/lib/protobuf-java-3.3.1.jar:/invoker/lib/gson-2.7.jar:/invoker/lib/aeron-driver-1.15.1.jar:/invoker/lib/aeron-client-1.15.1.jar:/invoker/lib/lmdbjava-0.6.1.jar:/invoker/lib/commons-collections4-4.2.jar:/invoker/lib/netty-buffer-4.1.32.Final.jar:/invoker/lib/netty-resolver-4.1.32.Final.jar:/invoker/lib/ion-java-1.0.2.jar:/invoker/lib/joda-time-2.8.1.jar:/invoker/lib/agrona-0.9.31.jar:/invoker/lib/jnr-ffi-2.1.7.jar:/invoker/lib/jnr-constants-0.9.9.jar:/invoker/lib/commons-digester-1.8.1.jar:/invoker/lib/failureaccess-1.0.1.jar:/invoker/lib/listenablefuture-9999.0-empty-to-avoid-conflict-with-guava.jar:/invoker/lib/checker-qual-2.5.2.jar:/invoker/lib/error_prone_annotations-2.2.0.jar:/invoker/lib/j2objc-annotations-1.1.jar:/invoker/lib/animal-sniffer-annotations-1.17.jar:/invoker/lib/netty-common-4.1.32.Final.jar:/invoker/lib/jffi-1.2.16.jar:/invoker/lib/jffi-1.2.16-native.jar:/invoker/lib/asm-commons-5.0.3.jar:/invoker/lib/asm-analysis-5.0.3.jar:/invoker/lib/asm-util-5.0.3.jar:/invoker/lib/asm-tree-5.0.3.jar:/invoker/lib/asm-5.0.3.jar:/invoker/lib/jnr-x86asm-1.0.2.jar:/invoker/ext-lib/*:/invoker/config
[2019-09-26T05:10:33.297Z] [INFO] Client environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
[2019-09-26T05:10:33.297Z] [INFO] Client environment:java.io.tmpdir=/tmp
[2019-09-26T05:10:33.297Z] [INFO] Client environment:java.compiler=<NA>
[2019-09-26T05:10:33.297Z] [INFO] Client environment:os.name=Linux
[2019-09-26T05:10:33.297Z] [INFO] Client environment:os.arch=amd64
[2019-09-26T05:10:33.297Z] [INFO] Client environment:os.version=4.15.0-64-generic
[2019-09-26T05:10:33.297Z] [INFO] Client environment:user.name=root
[2019-09-26T05:10:33.297Z] [INFO] Client environment:user.home=/root
[2019-09-26T05:10:33.297Z] [INFO] Client environment:user.dir=/
[2019-09-26T05:10:33.299Z] [INFO] Initiating client connection, connectString=owdev-zookeeper-0.owdev-zookeeper.openwhisk.svc.cluster.local:2181 sessionTimeout=60000 watcher=org.apache.curator.ConnectionState@3b9632d1
[2019-09-26T05:10:33.323Z] [INFO] Default schema
[2019-09-26T05:10:33.324Z] [INFO] Opening socket connection to server owdev-zookeeper-0.owdev-zookeeper.openwhisk.svc.cluster.local/10.244.1.137:2181. Will not attempt to authenticate using SASL (unknown error)
[2019-09-26T05:10:33.332Z] [INFO] Socket connection established to owdev-zookeeper-0.owdev-zookeeper.openwhisk.svc.cluster.local/10.244.1.137:2181, initiating session
[2019-09-26T05:10:33.338Z] [INFO] Session establishment complete on server owdev-zookeeper-0.owdev-zookeeper.openwhisk.svc.cluster.local/10.244.1.137:2181, sessionid = 0x1000177fa6d0001, negotiated timeout = 40000
[2019-09-26T05:10:33.346Z] [INFO] State change: CONNECTED
[2019-09-26T05:10:33.348Z] [INFO] [#tid_sid_unknown] [InstanceIdAssigner] invokerReg: connected to zookeeper
[2019-09-26T05:10:33.373Z] [INFO] [#tid_sid_unknown] [InstanceIdAssigner] invokerReg: no prior assignment of id for invoker ath-9
[2019-09-26T05:10:33.391Z] [WARN] The version of ZooKeeper being used doesn't support Container nodes. CreateMode.PERSISTENT will be used instead.
[2019-09-26T05:10:33.418Z] [INFO] backgroundOperationsLoop exiting
[2019-09-26T05:10:33.418Z] [INFO] [#tid_sid_unknown] [InstanceIdAssigner] invokerReg: invoker ath-9 was assigned invokerId 0
[2019-09-26T05:10:33.420Z] [INFO] Session: 0x1000177fa6d0001 closed
[2019-09-26T05:10:33.420Z] [INFO] EventThread shut down for session: 0x1000177fa6d0001
[2019-09-26T05:10:33.427Z] [INFO] The configuration was reloaded successfully.
[2019-09-26T05:10:34.087Z] [INFO] [#tid_sid_unknown] [KafkaMessagingProvider] created topic invoker0
[2019-09-26T05:10:34.244Z] [INFO] [#tid_sid_unknown] [InvokerReactive] LogStoreProvider: class org.apache.openwhisk.core.containerpool.logging.DockerToActivationLogStore
[2019-09-26T05:10:34.504Z] [INFO] [#tid_sid_unknown] [DockerClientWithFileAccess] Detected docker client version 18.06.3-ce
[2019-09-26T05:10:34.539Z] [INFO] [#tid_sid_invoker] [DockerClientWithFileAccess] running /usr/bin/docker ps --quiet --no-trunc --all --filter name=wskath-90_ (timeout: 1 minute) [marker:invoker_docker.ps_start:1812]
[2019-09-26T05:10:34.764Z] [INFO] [#tid_sid_invoker] [DockerClientWithFileAccess]  [marker:invoker_docker.ps_finish:2037:108]
[2019-09-26T05:10:34.778Z] [INFO] [#tid_sid_invoker] [DockerContainerFactory] removing 0 action containers.
[2019-09-26T05:10:35.500Z] [INFO] [#tid_sid_invoker] [CouchDbRestStore] [QUERY] 'test_subjects' searching 'namespaceThrottlings/blockedNamespaces [marker:database_queryView_start:2774]
[2019-09-26T05:10:35.723Z] [INFO] [#tid_sid_dispatcher] [MessageFeed] handler capacity = 16, pipeline fill at = 16, pipeline depth = 32
[2019-09-26T05:10:35.724Z] [INFO] [#tid_sid_invokerWarmup] [ContainerPool] pre-warming 2 nodejs:10 256 MB
[2019-09-26T05:10:35.844Z] [INFO] [#tid_sid_invoker] [CouchDbRestStore]  [marker:database_queryView_finish:3118:344]
[2019-09-26T05:10:35.845Z] [INFO] [#tid_sid_unknown] [InvokerReactive] updated blacklist to 0 entries
[2019-09-26T05:10:35.931Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 128 --memory 256m --memory-swap 256m --network bridge -e __OW_API_HOST=https://128.253.128.245:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-search ece.cornell.edu --dns-search coecis.cornell.edu --dns-option options --dns-option ndots:5 --name wskath-90_2_prewarm_nodejs10 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:3204]
[2019-09-26T05:10:35.931Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 128 --memory 256m --memory-swap 256m --network bridge -e __OW_API_HOST=https://128.253.128.245:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-search ece.cornell.edu --dns-search coecis.cornell.edu --dns-option options --dns-option ndots:5 --name wskath-90_1_prewarm_nodejs10 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:3204]
[2019-09-26T05:10:36.279Z] [INFO] [#tid_sid_invokerHealth] [InvokerReactive]  [marker:invoker_activation_start:14993]
[2019-09-26T05:10:36.287Z] [WARN] [#tid_sid_invokerHealth] [InvokerReactive] revision was not provided for whisk.system/invokerHealthTestAction0
[2019-09-26T05:10:36.394Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore] [GET] 'test_whisks' finding document: 'id: whisk.system/invokerHealthTestAction0' [marker:database_getDocument_start:15109]
[2019-09-26T05:10:36.418Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore]  [marker:database_getDocument_finish:15132:23]
[2019-09-26T05:10:36.458Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 64 --memory 128m --memory-swap 128m --network bridge -e __OW_API_HOST=https://128.253.128.245:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-search ece.cornell.edu --dns-search coecis.cornell.edu --dns-option options --dns-option ndots:5 --name wskath-90_3_whisksystem_invokerHealthTestAction0 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:15172]
[2019-09-26T05:10:36.459Z] [INFO] [#tid_sid_invokerHealth] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: invokerHealthTestAction0 namespace: whisk.system activationId: 14d12be7d6f14b24912be7d6f1bb24c4 [marker:invoker_containerStart.cold_counter:15173]
[2019-09-26T05:10:37.266Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:4539:1334]
[2019-09-26T05:10:37.283Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess] running /usr/bin/docker inspect --format {{.NetworkSettings.Networks.bridge.IPAddress}} 5f589f57cdf041b7e5a0a70a9361dc1d12406abc79a00432da6551ab9fab4ce6 (timeout: 1 minute) [marker:invoker_docker.inspect_start:4556]
[2019-09-26T05:10:37.383Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess]  [marker:invoker_docker.inspect_finish:4656:100]
[2019-09-26T05:10:37.476Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:4749:1545]
[2019-09-26T05:10:37.477Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess] running /usr/bin/docker inspect --format {{.NetworkSettings.Networks.bridge.IPAddress}} 77e356135898c2707734858213ba8f0c34ffbdbba1af1022d539ebf0c6c773ef (timeout: 1 minute) [marker:invoker_docker.inspect_start:4750]
[2019-09-26T05:10:37.563Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess]  [marker:invoker_docker.inspect_finish:4836:85]
[2019-09-26T05:10:37.737Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:16451:1278]
[2019-09-26T05:10:37.738Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker inspect --format {{.NetworkSettings.Networks.bridge.IPAddress}} 9d52bc09ba0825f8d0f23d7ae5d522b0c65c753523717ed4f4a6e4f93a3e1e27 (timeout: 1 minute) [marker:invoker_docker.inspect_start:16453]
[2019-09-26T05:10:37.831Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.inspect_finish:16545:92]
[2019-09-26T05:10:37.836Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending initialization to ContainerId(9d52bc09ba0825f8d0f23d7ae5d522b0c65c753523717ed4f4a6e4f93a3e1e27) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationInit_start:16550]
[2019-09-26T05:10:38.041Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] initialization result: ok [marker:invoker_activationInit_finish:16755:198]
[2019-09-26T05:10:38.049Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending arguments to /whisk.system/invokerHealthTestAction0 at ContainerId(9d52bc09ba0825f8d0f23d7ae5d522b0c65c753523717ed4f4a6e4f93a3e1e27) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationRun_start:16763]
[2019-09-26T05:10:38.061Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:16775:11]
[2019-09-26T05:10:38.075Z] [INFO] [#tid_sid_invokerHealth] [ContainerProxy]  [marker:invoker_collectLogs_start:16789]
[2019-09-26T05:10:38.105Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f 9d52bc09ba0825f8d0f23d7ae5d522b0c65c753523717ed4f4a6e4f93a3e1e27 (timeout: 1 minute) [marker:invoker_docker.rm_start:5378]
[2019-09-26T05:10:38.850Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:6123:745]
[2019-09-26T05:11:36.031Z] [INFO] [#tid_sid_invokerHealth] [InvokerReactive]  [marker:invoker_activation_start:74744]
[2019-09-26T05:11:36.032Z] [WARN] [#tid_sid_invokerHealth] [InvokerReactive] revision was not provided for whisk.system/invokerHealthTestAction0
[2019-09-26T05:11:36.032Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore] [GET] 'test_whisks' finding document: 'id: whisk.system/invokerHealthTestAction0' [marker:database_getDocument_start:74746]
[2019-09-26T05:11:36.097Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore]  [marker:database_getDocument_finish:74811:64]
[2019-09-26T05:11:36.101Z] [INFO] [#tid_sid_invokerHealth] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: invokerHealthTestAction0 namespace: whisk.system activationId: dc7bf896dba043f4bbf896dba0b3f44b [marker:invoker_containerStart.cold_counter:74815]
[2019-09-26T05:11:36.104Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 64 --memory 128m --memory-swap 128m --network bridge -e __OW_API_HOST=https://128.253.128.245:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-search ece.cornell.edu --dns-search coecis.cornell.edu --dns-option options --dns-option ndots:5 --name wskath-90_4_whisksystem_invokerHealthTestAction0 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:74818]
[2019-09-26T05:11:37.470Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:76184:1366]
[2019-09-26T05:11:37.472Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker inspect --format {{.NetworkSettings.Networks.bridge.IPAddress}} f55ae1da344cbb19b4063d30525b407e3f516e00dbbd9cfdfe7eed315948c970 (timeout: 1 minute) [marker:invoker_docker.inspect_start:76186]
[2019-09-26T05:11:37.567Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.inspect_finish:76281:95]
[2019-09-26T05:11:37.568Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending initialization to ContainerId(f55ae1da344cbb19b4063d30525b407e3f516e00dbbd9cfdfe7eed315948c970) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationInit_start:76282]
[2019-09-26T05:11:37.723Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] initialization result: ok [marker:invoker_activationInit_finish:76438:155]
[2019-09-26T05:11:37.724Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending arguments to /whisk.system/invokerHealthTestAction0 at ContainerId(f55ae1da344cbb19b4063d30525b407e3f516e00dbbd9cfdfe7eed315948c970) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationRun_start:76439]
[2019-09-26T05:11:37.734Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:76449:10]
[2019-09-26T05:11:37.736Z] [INFO] [#tid_sid_invokerHealth] [ContainerProxy]  [marker:invoker_collectLogs_start:76450]
[2019-09-26T05:11:37.739Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f f55ae1da344cbb19b4063d30525b407e3f516e00dbbd9cfdfe7eed315948c970 (timeout: 1 minute) [marker:invoker_docker.rm_start:65013]
[2019-09-26T05:11:38.386Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:65659:646]
[2019-09-26T05:12:36.025Z] [INFO] [#tid_sid_invokerHealth] [InvokerReactive]  [marker:invoker_activation_start:134740]
[2019-09-26T05:12:36.026Z] [WARN] [#tid_sid_invokerHealth] [InvokerReactive] revision was not provided for whisk.system/invokerHealthTestAction0
[2019-09-26T05:12:36.027Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore] [GET] 'test_whisks' finding document: 'id: whisk.system/invokerHealthTestAction0' [marker:database_getDocument_start:134740]
[2019-09-26T05:12:36.073Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore]  [marker:database_getDocument_finish:134788:48]
[2019-09-26T05:12:36.077Z] [INFO] [#tid_sid_invokerHealth] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: invokerHealthTestAction0 namespace: whisk.system activationId: ab6281c6f7324544a281c6f732154454 [marker:invoker_containerStart.cold_counter:134792]
[2019-09-26T05:12:36.079Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 64 --memory 128m --memory-swap 128m --network bridge -e __OW_API_HOST=https://128.253.128.245:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-search ece.cornell.edu --dns-search coecis.cornell.edu --dns-option options --dns-option ndots:5 --name wskath-90_5_whisksystem_invokerHealthTestAction0 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:134794]
[2019-09-26T05:12:37.396Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:136110:1316]
[2019-09-26T05:12:37.397Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker inspect --format {{.NetworkSettings.Networks.bridge.IPAddress}} 0192d06a6511ce9d1672acd76aeccffd78afd0d0f64048e39653c07700d67e9b (timeout: 1 minute) [marker:invoker_docker.inspect_start:136112]
[2019-09-26T05:12:37.499Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.inspect_finish:136213:101]
[2019-09-26T05:12:37.499Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending initialization to ContainerId(0192d06a6511ce9d1672acd76aeccffd78afd0d0f64048e39653c07700d67e9b) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationInit_start:136214]
[2019-09-26T05:12:37.586Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] initialization result: ok [marker:invoker_activationInit_finish:136301:86]
[2019-09-26T05:12:37.587Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending arguments to /whisk.system/invokerHealthTestAction0 at ContainerId(0192d06a6511ce9d1672acd76aeccffd78afd0d0f64048e39653c07700d67e9b) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationRun_start:136301]
[2019-09-26T05:12:37.594Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:136308:7]
[2019-09-26T05:12:37.595Z] [INFO] [#tid_sid_invokerHealth] [ContainerProxy]  [marker:invoker_collectLogs_start:136309]
[2019-09-26T05:12:37.598Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f 0192d06a6511ce9d1672acd76aeccffd78afd0d0f64048e39653c07700d67e9b (timeout: 1 minute) [marker:invoker_docker.rm_start:124871]
[2019-09-26T05:12:38.283Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:125557:686]
[2019-09-26T05:13:36.026Z] [INFO] [#tid_sid_invokerHealth] [InvokerReactive]  [marker:invoker_activation_start:194741]
[2019-09-26T05:13:36.027Z] [WARN] [#tid_sid_invokerHealth] [InvokerReactive] revision was not provided for whisk.system/invokerHealthTestAction0
[2019-09-26T05:13:36.027Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore] [GET] 'test_whisks' finding document: 'id: whisk.system/invokerHealthTestAction0' [marker:database_getDocument_start:194741]
[2019-09-26T05:13:36.073Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore]  [marker:database_getDocument_finish:194788:47]
[2019-09-26T05:13:36.076Z] [INFO] [#tid_sid_invokerHealth] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: invokerHealthTestAction0 namespace: whisk.system activationId: 4ccd8eebf50e47ea8d8eebf50ef7ea0d [marker:invoker_containerStart.cold_counter:194790]
[2019-09-26T05:13:36.079Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 64 --memory 128m --memory-swap 128m --network bridge -e __OW_API_HOST=https://128.253.128.245:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-search ece.cornell.edu --dns-search coecis.cornell.edu --dns-option options --dns-option ndots:5 --name wskath-90_6_whisksystem_invokerHealthTestAction0 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:194793]
[2019-09-26T05:13:37.354Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:196068:1275]
[2019-09-26T05:13:37.354Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker inspect --format {{.NetworkSettings.Networks.bridge.IPAddress}} 7bc7ddc7911790e49a76ac2c2a1614558e27a5a5b33164905986a203049a351c (timeout: 1 minute) [marker:invoker_docker.inspect_start:196069]
[2019-09-26T05:13:37.441Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.inspect_finish:196156:87]
[2019-09-26T05:13:37.442Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending initialization to ContainerId(7bc7ddc7911790e49a76ac2c2a1614558e27a5a5b33164905986a203049a351c) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationInit_start:196156]
[2019-09-26T05:13:37.580Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] initialization result: ok [marker:invoker_activationInit_finish:196295:138]
[2019-09-26T05:13:37.581Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending arguments to /whisk.system/invokerHealthTestAction0 at ContainerId(7bc7ddc7911790e49a76ac2c2a1614558e27a5a5b33164905986a203049a351c) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationRun_start:196296]
[2019-09-26T05:13:37.586Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:196301:5]
[2019-09-26T05:13:37.587Z] [INFO] [#tid_sid_invokerHealth] [ContainerProxy]  [marker:invoker_collectLogs_start:196302]
[2019-09-26T05:13:37.590Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f 7bc7ddc7911790e49a76ac2c2a1614558e27a5a5b33164905986a203049a351c (timeout: 1 minute) [marker:invoker_docker.rm_start:184864]
[2019-09-26T05:13:38.258Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:185531:667]
[2019-09-26T05:14:36.023Z] [INFO] [#tid_sid_invokerHealth] [InvokerReactive]  [marker:invoker_activation_start:254737]
[2019-09-26T05:14:36.023Z] [WARN] [#tid_sid_invokerHealth] [InvokerReactive] revision was not provided for whisk.system/invokerHealthTestAction0
[2019-09-26T05:14:36.023Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore] [GET] 'test_whisks' finding document: 'id: whisk.system/invokerHealthTestAction0' [marker:database_getDocument_start:254737]
[2019-09-26T05:14:36.064Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore]  [marker:database_getDocument_finish:254779:41]
[2019-09-26T05:14:36.067Z] [INFO] [#tid_sid_invokerHealth] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: invokerHealthTestAction0 namespace: whisk.system activationId: c458ee10d2ea47fc98ee10d2eab7fc76 [marker:invoker_containerStart.cold_counter:254781]
[2019-09-26T05:14:36.069Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 64 --memory 128m --memory-swap 128m --network bridge -e __OW_API_HOST=https://128.253.128.245:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-search ece.cornell.edu --dns-search coecis.cornell.edu --dns-option options --dns-option ndots:5 --name wskath-90_7_whisksystem_invokerHealthTestAction0 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:254784]
[2019-09-26T05:14:37.418Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:256132:1348]
[2019-09-26T05:14:37.419Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker inspect --format {{.NetworkSettings.Networks.bridge.IPAddress}} a52384107944ea92b328c7c8b50c3e68ee510e7ce60a9ff9a39c29da9d112cff (timeout: 1 minute) [marker:invoker_docker.inspect_start:256134]
[2019-09-26T05:14:37.531Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.inspect_finish:256246:112]
[2019-09-26T05:14:37.532Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending initialization to ContainerId(a52384107944ea92b328c7c8b50c3e68ee510e7ce60a9ff9a39c29da9d112cff) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationInit_start:256246]
[2019-09-26T05:14:37.617Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] initialization result: ok [marker:invoker_activationInit_finish:256332:86]
[2019-09-26T05:14:37.618Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending arguments to /whisk.system/invokerHealthTestAction0 at ContainerId(a52384107944ea92b328c7c8b50c3e68ee510e7ce60a9ff9a39c29da9d112cff) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationRun_start:256332]
[2019-09-26T05:14:37.624Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:256339:5]
[2019-09-26T05:14:37.625Z] [INFO] [#tid_sid_invokerHealth] [ContainerProxy]  [marker:invoker_collectLogs_start:256340]
[2019-09-26T05:14:37.628Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f a52384107944ea92b328c7c8b50c3e68ee510e7ce60a9ff9a39c29da9d112cff (timeout: 1 minute) [marker:invoker_docker.rm_start:244901]
[2019-09-26T05:14:38.302Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:245576:675]
[2019-09-26T05:15:35.524Z] [INFO] [#tid_sid_invoker] [CouchDbRestStore] [QUERY] 'test_subjects' searching 'namespaceThrottlings/blockedNamespaces [marker:database_queryView_start:302797]
[2019-09-26T05:15:35.575Z] [INFO] [#tid_sid_invoker] [CouchDbRestStore]  [marker:database_queryView_finish:302849:50]
[2019-09-26T05:15:35.576Z] [INFO] [#tid_sid_unknown] [InvokerReactive] updated blacklist to 0 entries
[2019-09-26T05:15:36.023Z] [INFO] [#tid_sid_invokerHealth] [InvokerReactive]  [marker:invoker_activation_start:314738]
[2019-09-26T05:15:36.024Z] [WARN] [#tid_sid_invokerHealth] [InvokerReactive] revision was not provided for whisk.system/invokerHealthTestAction0
[2019-09-26T05:15:36.024Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore] [GET] 'test_whisks' finding document: 'id: whisk.system/invokerHealthTestAction0' [marker:database_getDocument_start:314738]
[2019-09-26T05:15:36.037Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore]  [marker:database_getDocument_finish:314752:14]
[2019-09-26T05:15:36.042Z] [INFO] [#tid_sid_invokerHealth] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: invokerHealthTestAction0 namespace: whisk.system activationId: dfbc9d0a5e684c19bc9d0a5e680c1963 [marker:invoker_containerStart.cold_counter:314756]
[2019-09-26T05:15:36.043Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 64 --memory 128m --memory-swap 128m --network bridge -e __OW_API_HOST=https://128.253.128.245:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-search ece.cornell.edu --dns-search coecis.cornell.edu --dns-option options --dns-option ndots:5 --name wskath-90_8_whisksystem_invokerHealthTestAction0 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:314758]
[2019-09-26T05:15:37.348Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:316063:1305]
[2019-09-26T05:15:37.350Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker inspect --format {{.NetworkSettings.Networks.bridge.IPAddress}} 6e86bfc7db015140c4152df3daaa2cbc2d5dc96976892a8fd2921d509b9938e3 (timeout: 1 minute) [marker:invoker_docker.inspect_start:316064]
[2019-09-26T05:15:37.443Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.inspect_finish:316158:94]
[2019-09-26T05:15:37.444Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending initialization to ContainerId(6e86bfc7db015140c4152df3daaa2cbc2d5dc96976892a8fd2921d509b9938e3) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationInit_start:316158]
[2019-09-26T05:15:37.531Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] initialization result: ok [marker:invoker_activationInit_finish:316245:86]
[2019-09-26T05:15:37.531Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending arguments to /whisk.system/invokerHealthTestAction0 at ContainerId(6e86bfc7db015140c4152df3daaa2cbc2d5dc96976892a8fd2921d509b9938e3) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationRun_start:316246]
[2019-09-26T05:15:37.536Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:316251:5]
[2019-09-26T05:15:37.537Z] [INFO] [#tid_sid_invokerHealth] [ContainerProxy]  [marker:invoker_collectLogs_start:316252]
[2019-09-26T05:15:37.540Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f 6e86bfc7db015140c4152df3daaa2cbc2d5dc96976892a8fd2921d509b9938e3 (timeout: 1 minute) [marker:invoker_docker.rm_start:304813]
[2019-09-26T05:15:38.154Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:305427:614]
[2019-09-26T05:16:36.023Z] [INFO] [#tid_sid_invokerHealth] [InvokerReactive]  [marker:invoker_activation_start:374738]
[2019-09-26T05:16:36.024Z] [WARN] [#tid_sid_invokerHealth] [InvokerReactive] revision was not provided for whisk.system/invokerHealthTestAction0
[2019-09-26T05:16:36.024Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore] [GET] 'test_whisks' finding document: 'id: whisk.system/invokerHealthTestAction0' [marker:database_getDocument_start:374739]
[2019-09-26T05:16:36.067Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore]  [marker:database_getDocument_finish:374782:43]
[2019-09-26T05:16:36.071Z] [INFO] [#tid_sid_invokerHealth] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: invokerHealthTestAction0 namespace: whisk.system activationId: d2c78a8f9cfc4e6d878a8f9cfcce6d84 [marker:invoker_containerStart.cold_counter:374786]
[2019-09-26T05:16:36.074Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 64 --memory 128m --memory-swap 128m --network bridge -e __OW_API_HOST=https://128.253.128.245:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-search ece.cornell.edu --dns-search coecis.cornell.edu --dns-option options --dns-option ndots:5 --name wskath-90_9_whisksystem_invokerHealthTestAction0 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:374788]
[2019-09-26T05:16:37.441Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:376155:1367]
[2019-09-26T05:16:37.442Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker inspect --format {{.NetworkSettings.Networks.bridge.IPAddress}} fdf1b0db4e3009a40b6b4d2f170d190973342e711671bdfdbd347db7cfdadcad (timeout: 1 minute) [marker:invoker_docker.inspect_start:376156]
[2019-09-26T05:16:37.534Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.inspect_finish:376248:92]
[2019-09-26T05:16:37.534Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending initialization to ContainerId(fdf1b0db4e3009a40b6b4d2f170d190973342e711671bdfdbd347db7cfdadcad) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationInit_start:376249]
[2019-09-26T05:16:37.673Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] initialization result: ok [marker:invoker_activationInit_finish:376388:139]
[2019-09-26T05:16:37.674Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending arguments to /whisk.system/invokerHealthTestAction0 at ContainerId(fdf1b0db4e3009a40b6b4d2f170d190973342e711671bdfdbd347db7cfdadcad) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationRun_start:376388]
[2019-09-26T05:16:37.679Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:376394:5]
[2019-09-26T05:16:37.680Z] [INFO] [#tid_sid_invokerHealth] [ContainerProxy]  [marker:invoker_collectLogs_start:376395]
[2019-09-26T05:16:37.683Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f fdf1b0db4e3009a40b6b4d2f170d190973342e711671bdfdbd347db7cfdadcad (timeout: 1 minute) [marker:invoker_docker.rm_start:364957]
[2019-09-26T05:16:38.334Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:365607:650]
[2019-09-26T05:17:36.022Z] [INFO] [#tid_sid_invokerHealth] [InvokerReactive]  [marker:invoker_activation_start:434736]
[2019-09-26T05:17:36.024Z] [WARN] [#tid_sid_invokerHealth] [InvokerReactive] revision was not provided for whisk.system/invokerHealthTestAction0
[2019-09-26T05:17:36.024Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore] [GET] 'test_whisks' finding document: 'id: whisk.system/invokerHealthTestAction0' [marker:database_getDocument_start:434737]
[2019-09-26T05:17:36.063Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore]  [marker:database_getDocument_finish:434778:41]
[2019-09-26T05:17:36.065Z] [INFO] [#tid_sid_invokerHealth] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: invokerHealthTestAction0 namespace: whisk.system activationId: a6655513c7b6409fa55513c7b6709f6e [marker:invoker_containerStart.cold_counter:434780]
[2019-09-26T05:17:36.067Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 64 --memory 128m --memory-swap 128m --network bridge -e __OW_API_HOST=https://128.253.128.245:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-search ece.cornell.edu --dns-search coecis.cornell.edu --dns-option options --dns-option ndots:5 --name wskath-90_10_whisksystem_invokerHealthTestAction0 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:434782]
[2019-09-26T05:17:37.323Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:436037:1255]
[2019-09-26T05:17:37.324Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker inspect --format {{.NetworkSettings.Networks.bridge.IPAddress}} f50b19d941581e4c94584bdba7e754908755d23b3c78ce2ee60e00ff46e1b683 (timeout: 1 minute) [marker:invoker_docker.inspect_start:436039]
[2019-09-26T05:17:37.424Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.inspect_finish:436139:100]
[2019-09-26T05:17:37.425Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending initialization to ContainerId(f50b19d941581e4c94584bdba7e754908755d23b3c78ce2ee60e00ff46e1b683) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationInit_start:436140]
[2019-09-26T05:17:37.569Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] initialization result: ok [marker:invoker_activationInit_finish:436283:143]
[2019-09-26T05:17:37.569Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending arguments to /whisk.system/invokerHealthTestAction0 at ContainerId(f50b19d941581e4c94584bdba7e754908755d23b3c78ce2ee60e00ff46e1b683) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationRun_start:436284]
[2019-09-26T05:17:37.575Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:436290:6]
[2019-09-26T05:17:37.576Z] [INFO] [#tid_sid_invokerHealth] [ContainerProxy]  [marker:invoker_collectLogs_start:436291]
[2019-09-26T05:17:37.578Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker rm -f f50b19d941581e4c94584bdba7e754908755d23b3c78ce2ee60e00ff46e1b683 (timeout: 1 minute) [marker:invoker_docker.rm_start:424852]
[2019-09-26T05:17:38.327Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess]  [marker:invoker_docker.rm_finish:425600:748]
zyqCSL commented 5 years ago

And mycluster.yaml is as follows:

whisk:
  ingress:
    type: NodePort
    apiHostName: KUBE_NODE_IP_ADDRESS
    apiHostPort: 31001

nginx:
  httpsNodePort: 31001

k8s:
  persistence:
    enabled: false

providers:
  alarm:
    enabled: false

invoker:
  containerFactory:
    impl: "docker"
chetanmeh commented 5 years ago

Indeed Invoker logs are fine. Thenlets check Controller log. The LoadBalancer should indicate if its finding the healthy invokers.

Also can you access controller (say via port forward to 8080 on controller pod) and see the output of /invoker url. It should list the invoker state

zyqCSL commented 5 years ago

The controller log looks like this:

...
[2019-09-26T06:05:36.013Z] [INFO] [#tid_sid_invokerHealth] [ShardingContainerPoolBalancer] posting topic 'invoker0' with activation id '2349fb724f64408089fb724f64708063' [marker:controller_kafka_start:3314728]
[2019-09-26T06:05:36.016Z] [INFO] [#tid_sid_invokerHealth] [ShardingContainerPoolBalancer] posted to invoker0[0][55] [marker:controller_kafka_finish:3314731:3]
[2019-09-26T06:05:38.403Z] [INFO] [#tid_gckYi4xlPimXdBLCOu2E7Sk6zWIbGW4K] GET /invokers/healthy/count 
[2019-09-26T06:05:38.404Z] [INFO] [#tid_gckYi4xlPimXdBLCOu2E7Sk6zWIbGW4K] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:05:41.412Z] [INFO] [#tid_Nhmmr7iorjQTOUv62ZIJBM3jmSFDJBbV] GET /invokers/healthy/count 
[2019-09-26T06:05:41.412Z] [INFO] [#tid_Nhmmr7iorjQTOUv62ZIJBM3jmSFDJBbV] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:05:44.421Z] [INFO] [#tid_49g2tNBVrjCjtwRFEogj2yRQ4Fgo5dRF] GET /invokers/healthy/count 
[2019-09-26T06:05:44.422Z] [INFO] [#tid_49g2tNBVrjCjtwRFEogj2yRQ4Fgo5dRF] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:05:47.430Z] [INFO] [#tid_YRUpbRUSBXKzqURkum1iBj0Q6R7UAoIB] GET /invokers/healthy/count 
[2019-09-26T06:05:47.431Z] [INFO] [#tid_YRUpbRUSBXKzqURkum1iBj0Q6R7UAoIB] [BasicHttpService] [marker:http_get.200_counter:0:0]
[2019-09-26T06:05:50.438Z] [INFO] [#tid_tIhA0F6SIkH2PoogEUCh5lFhvl06y7jQ] GET /invokers/healthy/count 
[2019-09-26T06:05:50.439Z] [INFO] [#tid_tIhA0F6SIkH2PoogEUCh5lFhvl06y7jQ] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:05:53.447Z] [INFO] [#tid_T8QF9z8E3kdkusYHg24MDd28JihxMGGV] GET /invokers/healthy/count 
[2019-09-26T06:05:53.448Z] [INFO] [#tid_T8QF9z8E3kdkusYHg24MDd28JihxMGGV] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:05:56.456Z] [INFO] [#tid_nGd5mAvX0SLENU7X7gc7BN0J8TTlmA0E] GET /invokers/healthy/count 
[2019-09-26T06:05:56.457Z] [INFO] [#tid_nGd5mAvX0SLENU7X7gc7BN0J8TTlmA0E] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:05:59.464Z] [INFO] [#tid_RyTdHZ4MDEiqwVFspQ9NDrBy6BzQN9dX] GET /invokers/healthy/count 
[2019-09-26T06:05:59.464Z] [INFO] [#tid_RyTdHZ4MDEiqwVFspQ9NDrBy6BzQN9dX] [BasicHttpService] [marker:http_get.200_counter:0:0]
[2019-09-26T06:06:02.473Z] [INFO] [#tid_u42RgTI4NgEE1nWsN8FCFMZJ5AFT35yl] GET /invokers/healthy/count 
[2019-09-26T06:06:02.474Z] [INFO] [#tid_u42RgTI4NgEE1nWsN8FCFMZJ5AFT35yl] [BasicHttpService] [marker:http_get.200_counter:0:0]
[2019-09-26T06:06:05.482Z] [INFO] [#tid_5sPIB5MwZQVhTfOvyqFOzERjLwysBsga] GET /invokers/healthy/count 
[2019-09-26T06:06:05.482Z] [INFO] [#tid_5sPIB5MwZQVhTfOvyqFOzERjLwysBsga] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:06:08.490Z] [INFO] [#tid_CfiRbirRoqaIKLSYf7IdJr0gWGRYpI4A] GET /invokers/healthy/count 
[2019-09-26T06:06:08.490Z] [INFO] [#tid_CfiRbirRoqaIKLSYf7IdJr0gWGRYpI4A] [BasicHttpService] [marker:http_get.200_counter:0:0]
[2019-09-26T06:06:11.498Z] [INFO] [#tid_bIGn3MZGuUazw2msIne6hAo3HnaFuUcO] GET /invokers/healthy/count 
[2019-09-26T06:06:11.499Z] [INFO] [#tid_bIGn3MZGuUazw2msIne6hAo3HnaFuUcO] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:06:14.507Z] [INFO] [#tid_FMfuhQmCwop5co6bMXKVI0nDqJcJ6gzJ] GET /invokers/healthy/count 
[2019-09-26T06:06:14.507Z] [INFO] [#tid_FMfuhQmCwop5co6bMXKVI0nDqJcJ6gzJ] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:06:17.516Z] [INFO] [#tid_S4TG3DkPi3cf2WAJxOMapOGpGix037i7] GET /invokers/healthy/count 
[2019-09-26T06:06:17.517Z] [INFO] [#tid_S4TG3DkPi3cf2WAJxOMapOGpGix037i7] [BasicHttpService] [marker:http_get.200_counter:0:0]
[2019-09-26T06:06:20.524Z] [INFO] [#tid_pGU90HuW5UWH5AqNan2aUWgjSR9jStqp] GET /invokers/healthy/count 
[2019-09-26T06:06:20.525Z] [INFO] [#tid_pGU90HuW5UWH5AqNan2aUWgjSR9jStqp] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:06:23.534Z] [INFO] [#tid_E4eqanB2VDMHvmWYadvGaduRKBCaYRBo] GET /invokers/healthy/count 
[2019-09-26T06:06:23.535Z] [INFO] [#tid_E4eqanB2VDMHvmWYadvGaduRKBCaYRBo] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:06:26.543Z] [INFO] [#tid_sHj72cGKTEXCNL1hpQBAqaeJ8DTVU9sx] GET /invokers/healthy/count 
[2019-09-26T06:06:26.544Z] [INFO] [#tid_sHj72cGKTEXCNL1hpQBAqaeJ8DTVU9sx] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:06:29.552Z] [INFO] [#tid_cdDhbjOIoyNCyd3OD8ASLmbyWqeZHpTg] GET /invokers/healthy/count 
[2019-09-26T06:06:29.553Z] [INFO] [#tid_cdDhbjOIoyNCyd3OD8ASLmbyWqeZHpTg] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:06:32.561Z] [INFO] [#tid_oakJd0saQckBFYSURusqNGWzlASJ8SLR] GET /invokers/healthy/count 
[2019-09-26T06:06:32.562Z] [INFO] [#tid_oakJd0saQckBFYSURusqNGWzlASJ8SLR] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:06:35.569Z] [INFO] [#tid_wQvYCJgIiG3VK7uaXbj02f4gMVOvwu6B] GET /invokers/healthy/count 
[2019-09-26T06:06:35.570Z] [INFO] [#tid_wQvYCJgIiG3VK7uaXbj02f4gMVOvwu6B] [BasicHttpService] [marker:http_get.200_counter:1:1]
[2019-09-26T06:06:36.013Z] [INFO] [#tid_sid_invokerHealth] [ShardingContainerPoolBalancer] posting topic 'invoker0' with activation id '666671e47d754173a671e47d7581739b' [marker:controller_kafka_start:3374728]
...

Accessing controller indeed gives an error: 

{"code":"MMJ2zjwY5s6AQoo9gCbvCOEXhWod4Kfm","error":"The requested resource could not be found."}%

Do you have any idea what might cause this?

chetanmeh commented 5 years ago

Gave the wrong url. Try to access /invokers. Also if you want we can discuss this on OpenWhisk Slack channel as well.

zyqCSL commented 5 years ago

kafka log:

[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-10 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-13 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-16 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-19 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-2 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-5 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-8 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-11 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-14 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-17 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-20 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-23 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-26 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-29 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-32 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-35 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-38 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-0 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-3 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-6 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-9 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,740] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-12 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-15 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-18 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-21 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-24 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-27 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-30 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-33 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-36 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-39 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-42 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-45 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,741] INFO [Group Metadata Manager on Broker 0]: Scheduling loading of offsets and group metadata from __consumer_offsets-48 (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,768] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-22 in 27 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,769] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-25 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,770] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-28 in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,770] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-31 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,770] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-34 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,770] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-37 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,771] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-40 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,771] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-43 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,771] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-46 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,771] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-49 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,772] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-41 in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,772] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-44 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,772] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-47 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,772] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-1 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,772] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-4 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,773] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-7 in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,773] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-10 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,773] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-13 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,773] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-16 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,773] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-19 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,774] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-2 in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,774] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-5 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,774] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-8 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,774] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-11 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,774] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-14 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,775] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-17 in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,775] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-20 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,775] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-23 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,775] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-26 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,775] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-29 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,776] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-32 in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,776] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-35 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,776] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-38 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,776] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-0 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,776] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-3 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,776] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-6 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,776] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-9 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,777] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-12 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,777] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-15 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,777] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-18 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,777] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-21 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,777] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-24 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,777] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-27 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,777] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-30 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,778] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-33 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,778] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-36 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,778] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-39 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,778] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-42 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,778] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-45 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,779] INFO [Group Metadata Manager on Broker 0]: Finished loading offsets and group metadata from __consumer_offsets-48 in 0 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:10:24,848] INFO [GroupCoordinator 0]: Preparing to rebalance group cacheInvalidationcontroller0 with old generation 0 (__consumer_offsets-20) (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:24,848] INFO [GroupCoordinator 0]: Preparing to rebalance group completed0 with old generation 0 (__consumer_offsets-39) (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:24,858] INFO [GroupCoordinator 0]: Stabilized group completed0 generation 1 (__consumer_offsets-39) (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:24,864] INFO [GroupCoordinator 0]: Stabilized group cacheInvalidationcontroller0 generation 1 (__consumer_offsets-20) (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:24,869] INFO [GroupCoordinator 0]: Assignment received from leader for group cacheInvalidationcontroller0 for generation 1 (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:24,869] INFO [GroupCoordinator 0]: Assignment received from leader for group completed0 for generation 1 (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:24,912] INFO Updated PartitionLeaderEpoch. New: {epoch:0, offset:0}, Current: {epoch:-1, offset-1} for Partition: __consumer_offsets-39. Cache now contains 0 entries. (kafka.server.epoch.LeaderEpochFileCache)
[2019-09-26 05:10:24,912] INFO Updated PartitionLeaderEpoch. New: {epoch:0, offset:0}, Current: {epoch:-1, offset-1} for Partition: __consumer_offsets-20. Cache now contains 0 entries. (kafka.server.epoch.LeaderEpochFileCache)
[2019-09-26 05:10:24,950] INFO [GroupCoordinator 0]: Preparing to rebalance group health0 with old generation 0 (__consumer_offsets-26) (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:24,952] INFO [GroupCoordinator 0]: Stabilized group health0 generation 1 (__consumer_offsets-26) (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:24,954] INFO [GroupCoordinator 0]: Assignment received from leader for group health0 for generation 1 (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:24,956] INFO Updated PartitionLeaderEpoch. New: {epoch:0, offset:0}, Current: {epoch:-1, offset-1} for Partition: __consumer_offsets-26. Cache now contains 0 entries. (kafka.server.epoch.LeaderEpochFileCache)
[2019-09-26 05:10:34,061] INFO Topic creation {"version":1,"partitions":{"0":[0]}} (kafka.admin.AdminUtils$)
[2019-09-26 05:10:34,071] INFO [ReplicaFetcherManager on broker 0] Removed fetcher for partitions invoker0-0 (kafka.server.ReplicaFetcherManager)
[2019-09-26 05:10:34,077] INFO Loading producer state from offset 0 for partition invoker0-0 with message format version 2 (kafka.log.Log)
[2019-09-26 05:10:34,077] INFO Completed load of log invoker0-0 with 1 log segments, log start offset 0 and log end offset 0 in 2 ms (kafka.log.Log)
[2019-09-26 05:10:34,078] INFO Created log for partition [invoker0,0] in /kafka/kafka-logs-owdev-kafka-0 with properties {compression.type -> producer, message.format.version -> 0.11.0-IV2, file.delete.delay.ms -> 60000, max.message.bytes -> 1054612, min.compaction.lag.ms -> 0, message.timestamp.type -> CreateTime, min.insync.replicas -> 1, segment.jitter.ms -> 0, preallocate -> false, min.cleanable.dirty.ratio -> 0.5, index.interval.bytes -> 4096, unclean.leader.election.enable -> false, retention.bytes -> 1073741824, delete.retention.ms -> 86400000, cleanup.policy -> [delete], flush.ms -> 9223372036854775807, segment.ms -> 604800000, segment.bytes -> 536870912, retention.ms -> 172800000, message.timestamp.difference.max.ms -> 9223372036854775807, segment.index.bytes -> 10485760, flush.messages -> 9223372036854775807}. (kafka.log.LogManager)
[2019-09-26 05:10:34,081] INFO Partition [invoker0,0] on broker 0: No checkpointed highwatermark is found for partition invoker0-0 (kafka.cluster.Partition)
[2019-09-26 05:10:34,081] INFO Replica loaded for partition invoker0-0 with initial high watermark 0 (kafka.cluster.Replica)
[2019-09-26 05:10:34,081] INFO Partition [invoker0,0] on broker 0: invoker0-0 starts at Leader Epoch 0 from offset 0. Previous Leader Epoch was: -1 (kafka.cluster.Partition)
[2019-09-26 05:10:35,826] INFO [GroupCoordinator 0]: Preparing to rebalance group invoker0 with old generation 0 (__consumer_offsets-28) (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:35,828] INFO [GroupCoordinator 0]: Stabilized group invoker0 generation 1 (__consumer_offsets-28) (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:35,830] INFO [GroupCoordinator 0]: Assignment received from leader for group invoker0 for generation 1 (kafka.coordinator.group.GroupCoordinator)
[2019-09-26 05:10:35,831] INFO Updated PartitionLeaderEpoch. New: {epoch:0, offset:0}, Current: {epoch:-1, offset-1} for Partition: __consumer_offsets-28. Cache now contains 0 entries. (kafka.server.epoch.LeaderEpochFileCache)
[2019-09-26 05:10:35,916] INFO Updated PartitionLeaderEpoch. New: {epoch:0, offset:0}, Current: {epoch:-1, offset-1} for Partition: health-0. Cache now contains 0 entries. (kafka.server.epoch.LeaderEpochFileCache)
[2019-09-26 05:10:36,034] INFO Updated PartitionLeaderEpoch. New: {epoch:0, offset:0}, Current: {epoch:-1, offset-1} for Partition: invoker0-0. Cache now contains 0 entries. (kafka.server.epoch.LeaderEpochFileCache)
[2019-09-26 05:20:03,561] INFO [Group Metadata Manager on Broker 0]: Removed 0 expired offsets in 8 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:30:03,554] INFO [Group Metadata Manager on Broker 0]: Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:40:03,554] INFO [Group Metadata Manager on Broker 0]: Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 05:50:03,554] INFO [Group Metadata Manager on Broker 0]: Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 06:00:03,554] INFO [Group Metadata Manager on Broker 0]: Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 06:10:03,554] INFO [Group Metadata Manager on Broker 0]: Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 06:20:03,554] INFO [Group Metadata Manager on Broker 0]: Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 06:30:03,554] INFO [Group Metadata Manager on Broker 0]: Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
[2019-09-26 06:40:03,554] INFO [Group Metadata Manager on Broker 0]: Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.GroupMetadataManager)
zyqCSL commented 5 years ago

Full log attached. ctrl_log.txt

dgrove-oss commented 5 years ago

I think the problem is on the invoker side. I don't see any log messages indicating that log_collection has finished in your invoker log snippet. I'd expect a log sequence that looks like the appended (got this morning on Docker for Mac Kubernetes, using DockerContainerFactory).

[2019-09-26T13:35:27.701Z] [INFO] [#tid_sid_invokerHealth] [InvokerReactive]  [marker:invoker_activation_start:25728]
[2019-09-26T13:35:27.727Z] [WARN] [#tid_sid_invokerHealth] [InvokerReactive] revision was not provided for whisk.system/invokerHealthTestAction0
[2019-09-26T13:35:27.912Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore] [GET] 'test_whisks' finding document: 'id: whisk.system/invokerHealthTestAction0' [marker:database_getDocument_start:25940]
[2019-09-26T13:35:27.963Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:6545:962]
[2019-09-26T13:35:27.974Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore]  [marker:database_getDocument_finish:26001:61]
[2019-09-26T13:35:28.058Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess] running /usr/bin/docker run -d --cpu-shares 64 --memory 128m --memory-swap 128m --network bridge -e __OW_API_HOST=https://192.168.65.3:31001 -e __OW_ALLOW_CONCURRENT=false --dns 10.96.0.10 --dns-search openwhisk.svc.cluster.local --dns-search svc.cluster.local --dns-search cluster.local --dns-option options --dns-option ndots:5 --name wskdocker-desktop0_3_whisksystem_invokerHealthTestAction0 --cap-drop NET_RAW --cap-drop NET_ADMIN --ulimit nofile=1024:1024 --pids-limit 1024 --log-driver json-file openwhisk/action-nodejs-v10:1.14.0-incubating (timeout: 1 minute) [marker:invoker_docker.run_start:26085]
[2019-09-26T13:35:28.060Z] [INFO] [#tid_sid_invokerHealth] [ContainerPool] containerStart containerState: cold container: None activations: 1 of max 1 action: invokerHealthTestAction0 namespace: whisk.system activationId: f6f44cabb32d4e80b44cabb32dbe8043 [marker:invoker_containerStart.cold_counter:26087]
[2019-09-26T13:35:28.178Z] [INFO] [#tid_sid_invokerWarmup] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:6758:1167]
[2019-09-26T13:35:28.830Z] [INFO] [#tid_sid_invokerHealth] [DockerClientWithFileAccess]  [marker:invoker_docker.run_finish:26858:773]
[2019-09-26T13:35:28.836Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending initialization to ContainerId(d21c05d7d3c27eeb88e55fcd86c945998a2da5096aeefa61ec3b5545799b40c0) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationInit_start:26864]
[2019-09-26T13:35:29.237Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] initialization result: ok [marker:invoker_activationInit_finish:27264:391]
[2019-09-26T13:35:29.246Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] sending arguments to /whisk.system/invokerHealthTestAction0 at ContainerId(d21c05d7d3c27eeb88e55fcd86c945998a2da5096aeefa61ec3b5545799b40c0) ContainerAddress(172.17.0.4,8080) [marker:invoker_activationRun_start:27273]
[2019-09-26T13:35:29.257Z] [INFO] [#tid_sid_invokerHealth] [DockerContainer] running result: ok [marker:invoker_activationRun_finish:27284:10]
[2019-09-26T13:35:29.281Z] [INFO] [#tid_sid_invokerHealth] [ContainerProxy]  [marker:invoker_collectLogs_start:27309]
[2019-09-26T13:35:29.348Z] [INFO] [#tid_sid_invokerHealth] [ContainerProxy]  [marker:invoker_collectLogs_finish:27376:67]
[2019-09-26T13:35:29.370Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore] [PUT] 'test_activations' saving document: 'id: whisk.system/f6f44cabb32d4e80b44cabb32dbe8043, rev: null' [marker:database_saveDocument_start:27397]
[2019-09-26T13:35:29.375Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore] 'test_activations' saving 1 documents [marker:database_saveDocumentBulk_start:7959]
[2019-09-26T13:35:29.441Z] [INFO] [#tid_sid_invokerNanny] [DockerClientWithFileAccess] running /usr/bin/docker pause d21c05d7d3c27eeb88e55fcd86c945998a2da5096aeefa61ec3b5545799b40c0 (timeout: 10 seconds) [marker:invoker_docker.pause_start:8024]
[2019-09-26T13:35:29.469Z] [INFO] [#tid_sid_dbBatcher] [CouchDbRestStore]  [marker:database_saveDocumentBulk_finish:8053:94]
[2019-09-26T13:35:29.505Z] [INFO] [#tid_sid_invokerHealth] [InvokerReactive] posted completion of activation f6f44cabb32d4e80b44cabb32dbe8043
[2019-09-26T13:35:29.518Z] [INFO] [#tid_sid_invokerHealth] [CouchDbRestStore]  [marker:database_saveDocument_finish:27546:148]
zyqCSL commented 5 years ago

Seems an issue with DockerContainerFactory. After switching to KubernetesFactory, install package completes successfully. Thank you guys for the help!