· 6 years ago · Jan 11, 2020, 07:02 PM
12020-01-11 18:52:25 kubewatch [11 TMainThread] 1.0.0 DEBUG: looking up ID for namespace default
22020-01-11 18:52:25 kubewatch [11 TMainThread] 1.0.0 DEBUG: cluster ID URL is d6e_id://47652ec5-315f-42ea-8fe5-7bc69a484150/default
32020-01-11 18:52:26 kubewatch [11 TMainThread] 1.0.0 DEBUG: CRD type definition not found for hosts.getambassador.io
42020-01-11 18:52:26 kubewatch [11 TMainThread] 1.0.0 DEBUG: Host CRDs are not available. To enable CRD support, configure the Ambassador CRD type definitions and RBAC, then restart the Ambassador pod.
52020-01-11 18:52:26 kubewatch [11 TMainThread] 1.0.0 DEBUG: cluster ID is 21c17359-c729-50ea-82fa-60e08a28a6b1 (from namespace default)
62020-01-11 18:52:26 AMBASSADOR INFO starting with environment:
72020-01-11 18:52:26 AMBASSADOR INFO ====
8AMBASSADOR_ADMIN_PORT=tcp://10.43.126.201:8877
9AMBASSADOR_ADMIN_PORT_8877_TCP=tcp://10.43.126.201:8877
10AMBASSADOR_ADMIN_PORT_8877_TCP_ADDR=10.43.126.201
11AMBASSADOR_ADMIN_PORT_8877_TCP_PORT=8877
12AMBASSADOR_ADMIN_PORT_8877_TCP_PROTO=tcp
13AMBASSADOR_ADMIN_SERVICE_HOST=10.43.126.201
14AMBASSADOR_ADMIN_SERVICE_PORT=8877
15AMBASSADOR_ADMIN_SERVICE_PORT_AMBASSADOR_ADMIN=8877
16AMBASSADOR_ADMIN_URL=http://127.0.0.1:8877
17AMBASSADOR_CLUSTER_ID=21c17359-c729-50ea-82fa-60e08a28a6b1
18AMBASSADOR_CONFIG_BASE_DIR=/ambassador
19AMBASSADOR_INTERNAL_URL=https://127.0.0.1:8443
20AMBASSADOR_NAMESPACE=default
21AMBASSADOR_PORT=tcp://10.43.20.110:80
22AMBASSADOR_PORT_443_TCP=tcp://10.43.20.110:443
23AMBASSADOR_PORT_443_TCP_ADDR=10.43.20.110
24AMBASSADOR_PORT_443_TCP_PORT=443
25AMBASSADOR_PORT_443_TCP_PROTO=tcp
26AMBASSADOR_PORT_80_TCP=tcp://10.43.20.110:80
27AMBASSADOR_PORT_80_TCP_ADDR=10.43.20.110
28AMBASSADOR_PORT_80_TCP_PORT=80
29AMBASSADOR_PORT_80_TCP_PROTO=tcp
30AMBASSADOR_REDIS_PORT=tcp://10.43.246.30:6379
31AMBASSADOR_REDIS_PORT_6379_TCP=tcp://10.43.246.30:6379
32AMBASSADOR_REDIS_PORT_6379_TCP_ADDR=10.43.246.30
33AMBASSADOR_REDIS_PORT_6379_TCP_PORT=6379
34AMBASSADOR_REDIS_PORT_6379_TCP_PROTO=tcp
35AMBASSADOR_REDIS_SERVICE_HOST=10.43.246.30
36AMBASSADOR_REDIS_SERVICE_PORT=6379
37AMBASSADOR_SERVICE_HOST=10.43.20.110
38AMBASSADOR_SERVICE_PORT=80
39AMBASSADOR_SERVICE_PORT_HTTP=80
40AMBASSADOR_SERVICE_PORT_HTTPS=443
41AMBASSADOR_URL=https://ambassador.default.svc.cluster.local
422020-01-11 18:52:26 AMBASSADOR INFO ====
432020-01-11 18:52:26 AMBASSADOR INFO launching worker process 'ambex': 'ambex' '-ads' '8003' '/ambassador/envoy'
442020-01-11 18:52:26 AMBASSADOR INFO ambex is PID 287
452020-01-11 18:52:26 AMBASSADOR INFO launching worker process 'diagd': 'diagd' '/ambassador/snapshots' '/ambassador/bootstrap-ads.json' '/ambassador/envoy/envoy.json' '--notices' '/ambassador/notices.json' '--kick' 'kill -HUP 1'
46time="2020-01-11T18:52:26Z" level=info msg="Ambex 1.0.0 starting..."
47time="2020-01-11T18:52:26Z" level=info msg=Listening port=8003
482020-01-11 18:52:26 AMBASSADOR INFO diagd is PID 295
49time="2020-01-11T18:52:26Z" level=info msg="Wrote PID" file=ambex.pid pid=287
50time="2020-01-11T18:52:26Z" level=info msg="Pushing snapshot v0"
512020-01-11 18:52:26 diagd 1.0.0 [P295TMainThread] INFO: thread count 33, listening on 0.0.0.0:8877
522020-01-11 18:52:26 diagd 1.0.0 [P295TMainThread] INFO: BOOT: Scout result {"latest_version": "1.0.0", "cached": false, "timestamp": 1578768746.885438}
53[2020-01-11 18:52:26 +0000] [295] [INFO] Starting gunicorn 19.9.0
54[2020-01-11 18:52:26 +0000] [295] [INFO] Listening at: http://0.0.0.0:8877 (295)
55[2020-01-11 18:52:26 +0000] [295] [INFO] Using worker: threads
56[2020-01-11 18:52:26 +0000] [303] [INFO] Booting worker with pid: 303
572020-01-11 18:52:26 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: starting Scout checker
582020-01-11 18:52:26 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: starting event watcher
592020-01-11 18:52:27 AMBASSADOR INFO diagd running
602020-01-11 18:52:27 AMBASSADOR INFO launching worker process 'watt': 'watt' '--port' '8002' '--notify' 'python /ambassador/post_update.py --watt ' '-s' 'service' '-s' 'ingresses' '-s' 'AuthService' '-s' 'Mapping' '-s' 'Module' '-s' 'RateLimitService' '-s' 'TCPMapping' '-s' 'TLSContext' '-s' 'TracingService' '-s' 'ConsulResolver' '-s' 'KubernetesEndpointResolver' '-s' 'KubernetesServiceResolver' '-s' 'LogService' '--watch' 'python /ambassador/watch_hook.py'
612020-01-11 18:52:27 AMBASSADOR INFO watt is PID 312
622020-01-11 18:52:27 AMBASSADOR INFO launching worker process 'amb-sidecar': '/ambassador/sidecars/amb-sidecar'
632020-01-11 18:52:27 AMBASSADOR INFO amb-sidecar is PID 320
64time="2020-01-11 18:52:27" level=error msg="error validating license key from file /.config/ambassador/license-key: Token validation error: token contains an invalid number of segments: errorFlags=0x00000001=(ValidationErrorMalformed) wrappedError=(<nil>)"
652020/01/11 18:52:27 starting watt...
662020/01/11 18:52:27 kubebootstrap: starting
672020/01/11 18:52:27 consulwatchman: starting
682020/01/11 18:52:27 kubewatchman: starting
692020/01/11 18:52:27 aggregator: starting
702020/01/11 18:52:27 invoker: starting
712020/01/11 18:52:27 api: starting
722020/01/11 18:52:27 api: snapshot server listening on: :8002
732020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "service" in namespace "*"
742020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "ingresses" in namespace "*"
752020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "AuthService" in namespace "*"
76time="2020-01-11 18:52:27" level=info msg="Ambassador Edge Stack configuation loaded"
77time="2020-01-11 18:52:27" level=info msg="Loading content from git repo" contentBranch=master contentSubdir=/ contentURL="https://github.com/datawire/devportal-content.git" subsystem=content
78time="2020-01-11 18:52:27" level=info msg="Creating watch on /.config/ambassador/"
792020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "Mapping" in namespace "*"
802020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "Module" in namespace "*"
812020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "RateLimitService" in namespace "*"
822020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "TCPMapping" in namespace "*"
83time="2020-01-11 18:52:27" level=info msg="initial count 0" MAIN=ratelimit_controller
842020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "TLSContext" in namespace "*"
85time="2020-01-11 18:52:27" level=debug msg="goroutine exited without error" MAIN=ratelimit_controller
862020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "TracingService" in namespace "*"
87time="2020-01-11 18:52:27" level=debug msg="goroutine exited without error" MAIN=auth_controller
882020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "ConsulResolver" in namespace "*"
892020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "KubernetesEndpointResolver" in namespace "*"
902020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "KubernetesServiceResolver" in namespace "*"
912020/01/11 18:52:27 kubebootstrap: adding kubernetes watch for "LogService" in namespace "*"
922020/01/11 18:52:27 kubebootstrap: found 0 "KubernetesServiceResolver" in namespace "*"
932020/01/11 18:52:27 kubebootstrap: sent "KubernetesServiceResolver" to 1 receivers
942020/01/11 18:52:27 kubebootstrap: found 10 "service" in namespace "*"
952020/01/11 18:52:27 kubebootstrap: sent "service" to 1 receivers
962020/01/11 18:52:27 kubebootstrap: found 0 "TCPMapping" in namespace "*"
972020/01/11 18:52:27 kubebootstrap: sent "TCPMapping" to 1 receivers
982020/01/11 18:52:27 kubebootstrap: found 0 "TracingService" in namespace "*"
992020/01/11 18:52:27 kubebootstrap: sent "TracingService" to 1 receivers
1002020/01/11 18:52:27 kubebootstrap: found 0 "Module" in namespace "*"
1012020/01/11 18:52:27 kubebootstrap: sent "Module" to 1 receivers
1022020/01/11 18:52:27 kubebootstrap: found 0 "RateLimitService" in namespace "*"
1032020/01/11 18:52:27 kubebootstrap: sent "RateLimitService" to 1 receivers
1042020/01/11 18:52:27 kubebootstrap: found 1 "TLSContext" in namespace "*"
1052020/01/11 18:52:27 kubebootstrap: sent "TLSContext" to 1 receivers
1062020/01/11 18:52:27 kubebootstrap: found 0 "ConsulResolver" in namespace "*"
1072020/01/11 18:52:27 kubebootstrap: sent "ConsulResolver" to 1 receivers
1082020/01/11 18:52:27 kubebootstrap: found 0 "KubernetesEndpointResolver" in namespace "*"
1092020/01/11 18:52:27 kubebootstrap: sent "KubernetesEndpointResolver" to 1 receivers
1102020/01/11 18:52:27 kubebootstrap: found 0 "ingresses" in namespace "*"
1112020/01/11 18:52:27 kubebootstrap: sent "ingresses" to 1 receivers
1122020/01/11 18:52:27 kubebootstrap: found 0 "AuthService" in namespace "*"
1132020/01/11 18:52:27 kubebootstrap: sent "AuthService" to 1 receivers
1142020/01/11 18:52:27 kubebootstrap: found 1 "Mapping" in namespace "*"
1152020/01/11 18:52:27 kubebootstrap: sent "Mapping" to 1 receivers
1162020/01/11 18:52:27 kubebootstrap: found 0 "LogService" in namespace "*"
1172020/01/11 18:52:27 kubebootstrap: sent "LogService" to 1 receivers
1182020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: reading edge-stack-mappings.yaml (/ambassador/init-config/edge-stack-mappings.yaml)
1192020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: YAML: using C parser
1202020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: YAML: using C dumper
1212020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook ERROR: -global-: <RichStatus BAD error=Ambassador could not find the Host CRD definition. Please visit https://www.getambassador.io/reference/core/crds/ for more information. You can continue using Ambassador via Kubernetes annotations, any configuration via CRDs will be ignored... hostname=aes-69bbd5db9c-rwgcx version=1.0.0>
1222020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook ERROR: ERROR ERROR ERROR Starting with configuration errors
1232020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: IRTLSContext setup good: {
1242020/01/11 18:52:28 aggregator: watch hook stderr: "_active": false,
1252020/01/11 18:52:28 aggregator: watch hook stderr: "_errored": false,
1262020/01/11 18:52:28 aggregator: watch hook stderr: "_rkey": "tls.default.1",
1272020/01/11 18:52:28 aggregator: watch hook stderr: "hosts": [
1282020/01/11 18:52:28 aggregator: watch hook stderr: "*"
1292020/01/11 18:52:28 aggregator: watch hook stderr: ],
1302020/01/11 18:52:28 aggregator: watch hook stderr: "is_fallback": false,
1312020/01/11 18:52:28 aggregator: watch hook stderr: "kind": "TLSContext",
1322020/01/11 18:52:28 aggregator: watch hook stderr: "location": "tls.default.1",
1332020/01/11 18:52:28 aggregator: watch hook stderr: "metadata_labels": {
1342020/01/11 18:52:28 aggregator: watch hook stderr: "ambassador_crd": "tls.default"
1352020/01/11 18:52:28 aggregator: watch hook stderr: },
1362020/01/11 18:52:28 aggregator: watch hook stderr: "name": "tls",
1372020/01/11 18:52:28 aggregator: watch hook stderr: "namespace": "default",
1382020/01/11 18:52:28 aggregator: watch hook stderr: "secret_info": {
1392020/01/11 18:52:28 aggregator: watch hook stderr: "secret": "tls-cert"
1402020/01/11 18:52:28 aggregator: watch hook stderr: }
1412020/01/11 18:52:28 aggregator: watch hook stderr: }
1422020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: IR: watching Edge Stack; wizard allowed
1432020/01/11 18:52:28 aggregator: watch hook stderr:
1442020/01/11 18:52:28 aggregator: found 2 kubernetes watches
1452020/01/11 18:52:28 aggregator: found 0 consul watches
1462020/01/11 18:52:28 aggregator: waiting for k8s watch: secret|default|metadata.name=tls-cert|*
1472020/01/11 18:52:28 aggregator: waiting for k8s watch: TLSContext|default|*|*
1482020/01/11 18:52:28 consulwatchman: processing 0 consul watches
1492020/01/11 18:52:28 kubewatchman: processing 2 kubernetes watch specs
1502020/01/11 18:52:28 kubewatchman: add kubernetes watcher kubernetes:secret|default|metadata.name=tls-cert|*
1512020/01/11 18:52:28 kubewatchman: add kubernetes watcher kubernetes:TLSContext|default|*|*
1522020/01/11 18:52:28 kubernetes:secret|default|metadata.name=tls-cert|*: starting
1532020/01/11 18:52:28 kubernetes:TLSContext|default|*|*: starting
1542020/01/11 18:52:28 kubernetes:TLSContext|default|*|*: found 1 "TLSContext" in namespace "default"
1552020/01/11 18:52:28 kubernetes:TLSContext|default|*|*: sent "TLSContext" to receivers
1562020/01/11 18:52:28 kubernetes:secret|default|metadata.name=tls-cert|*: found 1 "secret" in namespace "default"
1572020/01/11 18:52:28 kubernetes:secret|default|metadata.name=tls-cert|*: sent "secret" to receivers
1582020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: reading edge-stack-mappings.yaml (/ambassador/init-config/edge-stack-mappings.yaml)
1592020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: YAML: using C parser
1602020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: YAML: using C dumper
1612020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook ERROR: -global-: <RichStatus BAD error=Ambassador could not find the Host CRD definition. Please visit https://www.getambassador.io/reference/core/crds/ for more information. You can continue using Ambassador via Kubernetes annotations, any configuration via CRDs will be ignored... hostname=aes-69bbd5db9c-rwgcx version=1.0.0>
1622020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: dropping K8s dup TLSContext/tls.default
1632020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook ERROR: ERROR ERROR ERROR Starting with configuration errors
1642020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: IRTLSContext setup good: {
1652020/01/11 18:52:28 aggregator: watch hook stderr: "_active": false,
1662020/01/11 18:52:28 aggregator: watch hook stderr: "_errored": false,
1672020/01/11 18:52:28 aggregator: watch hook stderr: "_rkey": "tls.default.1",
1682020/01/11 18:52:28 aggregator: watch hook stderr: "hosts": [
1692020/01/11 18:52:28 aggregator: watch hook stderr: "*"
1702020/01/11 18:52:28 aggregator: watch hook stderr: ],
1712020/01/11 18:52:28 aggregator: watch hook stderr: "is_fallback": false,
1722020/01/11 18:52:28 aggregator: watch hook stderr: "kind": "TLSContext",
1732020/01/11 18:52:28 aggregator: watch hook stderr: "location": "tls.default.1",
1742020/01/11 18:52:28 aggregator: watch hook stderr: "metadata_labels": {
1752020/01/11 18:52:28 aggregator: watch hook stderr: "ambassador_crd": "tls.default"
1762020/01/11 18:52:28 aggregator: watch hook stderr: },
1772020/01/11 18:52:28 aggregator: watch hook stderr: "name": "tls",
1782020/01/11 18:52:28 aggregator: watch hook stderr: "namespace": "default",
1792020/01/11 18:52:28 aggregator: watch hook stderr: "secret_info": {
1802020/01/11 18:52:28 aggregator: watch hook stderr: "secret": "tls-cert"
1812020/01/11 18:52:28 aggregator: watch hook stderr: }
1822020/01/11 18:52:28 aggregator: watch hook stderr: }
1832020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: IR: watching Edge Stack; wizard allowed
1842020/01/11 18:52:28 aggregator: watch hook stderr:
1852020/01/11 18:52:28 aggregator: found 2 kubernetes watches
1862020/01/11 18:52:28 aggregator: found 0 consul watches
1872020/01/11 18:52:28 aggregator: initialized k8s watch: secret|default|metadata.name=tls-cert|*
1882020/01/11 18:52:28 aggregator: initialized k8s watch: TLSContext|default|*|*
1892020/01/11 18:52:28 aggregator: bootstrapped!
1902020/01/11 18:52:28 kubewatchman: processing 2 kubernetes watch specs
1912020/01/11 18:52:28 consulwatchman: processing 0 consul watches
1922020/01/11 18:52:28 notify: python /ambassador/post_update.py --watt http://localhost:8002/snapshots/1
1932020-01-11 18:52:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_2] INFO: Update requested: watt, http://localhost:8002/snapshots/1
1942020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: copying configuration: watt, http://localhost:8002/snapshots/1 to /ambassador/snapshots/snapshot-tmp.yaml
1952020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: reading edge-stack-mappings.yaml (/ambassador/init-config/edge-stack-mappings.yaml)
1962020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: YAML: using C parser
1972020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: YAML: using C dumper
1982020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] ERROR: -global-: <RichStatus BAD error=Ambassador could not find the Host CRD definition. Please visit https://www.getambassador.io/reference/core/crds/ for more information. You can continue using Ambassador via Kubernetes annotations, any configuration via CRDs will be ignored... hostname=aes-69bbd5db9c-rwgcx version=1.0.0>
1992020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: dropping K8s dup TLSContext/tls.default
2002020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] ERROR: ERROR ERROR ERROR Starting with configuration errors
2012020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: IRTLSContext setup good: {
202 "_active": false,
203 "_errored": false,
204 "_rkey": "tls.default.1",
205 "hosts": [
206 "*"
207 ],
208 "is_fallback": false,
209 "kind": "TLSContext",
210 "location": "tls.default.1",
211 "metadata_labels": {
212 "ambassador_crd": "tls.default"
213 },
214 "name": "tls",
215 "namespace": "default",
216 "secret_info": {
217 "secret": "tls-cert"
218 }
219}
2202020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: IR: starting Edge Stack; wizard allowed
2212020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: ListenerFactory: AT START
2222020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: listeners: {}
2232020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: unused_contexts: {
224 "*": "<IRTLSContext tls: hosts ['*'] secret tls-cert>"
225}
2262020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: ListenerFactory: AFTER HOSTS
2272020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: listeners: {}
2282020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: unused_contexts: {
229 "*": "<IRTLSContext tls: hosts ['*'] secret tls-cert>"
230}
2312020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: ListenerFactory: AFTER CONTEXTS
2322020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: listeners: {
233 "*": "<Listener ir.listener for *:8443, ctx tls, secure Route, insecure Reject/None>"
234}
2352020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: unused_contexts: {}
2362020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: ListenerFactory: AFTER FALLBACK
2372020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: listeners: {
238 "*": "<Listener ir.listener for *:8443, ctx tls, secure Route, insecure Reject/None>"
239}
2402020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: unused_contexts: {}
2412020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: working on <Listener ir.listener for *:8443, ctx tls, secure Route, insecure Reject/None>
2422020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listener ambassador-listener-8443 created
2432020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listener: Using log_format 'ACCESS [%START_TIME%] "%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% "%REQ(X-FORWARDED-FOR)%" "%REQ(USER-AGENT)%" "%REQ(X-REQUEST-ID)%" "%REQ(:AUTHORITY)%" "%UPSTREAM_HOST%"'
2442020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listener ambassador-listener-8443: adding VHost * for host *, secure Route, insecure Reject)
2452020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: distinct domain count 1, global SNI disabled
2462020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: {
247 "8443": {
248 "address": {
249 "socket_address": {
250 "address": "0.0.0.0",
251 "port_value": 8443,
252 "protocol": "TCP"
253 }
254 },
255 "name": "ambassador-listener-8443",
256 "vhosts": {
257 "*": {
258 "_action": "Route",
259 "_hostname": "*",
260 "_insecure_action": "Reject",
261 "_needs_redirect": false,
262 "_secure": true,
263 "routes": [],
264 "tls_context": {
265 "common_tls_context": {
266 "tls_certificates": [
267 {
268 "certificate_chain": {
269 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.crt"
270 },
271 "private_key": {
272 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.key"
273 }
274 }
275 ]
276 }
277 },
278 "use_proxy_proto": false
279 }
280 }
281 }
282}
2832020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
284 "_precedence": 1000000,
285 "match": {
286 "case_sensitive": true,
287 "prefix": "/.ambassador/",
288 "runtime_fraction": {
289 "default_value": {
290 "denominator": "HUNDRED",
291 "numerator": 100
292 },
293 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
294 }
295 },
296 "route": {
297 "cluster": "cluster_127_0_0_1_8500_default",
298 "priority": null,
299 "timeout": "3.000s"
300 }
301}...
3022020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
3032020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
3042020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
305 "_precedence": 1000000,
306 "match": {
307 "case_sensitive": true,
308 "prefix": "/edge_stack/",
309 "runtime_fraction": {
310 "default_value": {2020-01-11 18:50:01 kubewatch [10 TMainThread] 0.86.1 DEBUG: looking up ID for namespace default
3112020-01-11 18:50:01 kubewatch [10 TMainThread] 0.86.1 DEBUG: cluster ID URL is d6e_id://47652ec5-315f-42ea-8fe5-7bc69a484150/default
3122020-01-11 18:50:02 kubewatch [10 TMainThread] 0.86.1 DEBUG: cluster ID is 21c17359-c729-50ea-82fa-60e08a28a6b1 (from namespace default)
3132020-01-11 18:50:02 AMBASSADOR INFO starting with environment:
3142020-01-11 18:50:02 AMBASSADOR INFO ====
315AMBASSADOR_ADMIN_PORT=tcp://10.43.126.201:8877
316AMBASSADOR_ADMIN_PORT_8877_TCP=tcp://10.43.126.201:8877
317AMBASSADOR_ADMIN_PORT_8877_TCP_ADDR=10.43.126.201
318AMBASSADOR_ADMIN_PORT_8877_TCP_PORT=8877
319AMBASSADOR_ADMIN_PORT_8877_TCP_PROTO=tcp
320AMBASSADOR_ADMIN_SERVICE_HOST=10.43.126.201
321AMBASSADOR_ADMIN_SERVICE_PORT=8877
322AMBASSADOR_ADMIN_SERVICE_PORT_AMBASSADOR_ADMIN=8877
323AMBASSADOR_CLUSTER_ID=21c17359-c729-50ea-82fa-60e08a28a6b1
324AMBASSADOR_CONFIG_BASE_DIR=/ambassador
325AMBASSADOR_NAMESPACE=default
326AMBASSADOR_PORT=tcp://10.43.20.110:80
327AMBASSADOR_PORT_443_TCP=tcp://10.43.20.110:443
328AMBASSADOR_PORT_443_TCP_ADDR=10.43.20.110
329AMBASSADOR_PORT_443_TCP_PORT=443
330AMBASSADOR_PORT_443_TCP_PROTO=tcp
331AMBASSADOR_PORT_80_TCP=tcp://10.43.20.110:80
332AMBASSADOR_PORT_80_TCP_ADDR=10.43.20.110
333AMBASSADOR_PORT_80_TCP_PORT=80
334AMBASSADOR_PORT_80_TCP_PROTO=tcp
335AMBASSADOR_SERVICE_HOST=10.43.20.110
336AMBASSADOR_SERVICE_PORT=80
337AMBASSADOR_SERVICE_PORT_HTTP=80
338AMBASSADOR_SERVICE_PORT_HTTPS=443
3392020-01-11 18:50:02 AMBASSADOR INFO ====
3402020-01-11 18:50:02 AMBASSADOR INFO launching worker process 'ambex': 'ambex' '-ads' '8003' '/ambassador/envoy'
3412020-01-11 18:50:02 AMBASSADOR INFO ambex is PID 267
3422020-01-11 18:50:02 AMBASSADOR INFO launching worker process 'diagd': 'diagd' '/ambassador/snapshots' '/ambassador/bootstrap-ads.json' '/ambassador/envoy/envoy.json' '--notices' '/ambassador/notices.json' '--kick' 'kill -HUP 1'
343time="2020-01-11T18:50:02Z" level=info msg="Ambex -no-version- starting..."
3442020-01-11 18:50:02 AMBASSADOR INFO diagd is PID 275
345time="2020-01-11T18:50:02Z" level=info msg=Listening port=8003
346time="2020-01-11T18:50:02Z" level=info msg="Wrote PID" file=ambex.pid pid=267
347time="2020-01-11T18:50:02Z" level=info msg="Pushing snapshot v0"
3482020-01-11 18:50:02 diagd 0.86.1 [P275TMainThread] INFO: thread count 33, listening on 0.0.0.0:8877
3492020-01-11 18:50:03 diagd 0.86.1 [P275TMainThread] INFO: BOOT: Scout result {"latest_version": "0.86.1", "application": "ambassador", "cached": false, "timestamp": 1578768603.69401}
350[2020-01-11 18:50:03 +0000] [275] [INFO] Starting gunicorn 19.9.0
351[2020-01-11 18:50:03 +0000] [275] [INFO] Listening at: http://0.0.0.0:8877 (275)
352[2020-01-11 18:50:03 +0000] [275] [INFO] Using worker: threads
353[2020-01-11 18:50:03 +0000] [286] [INFO] Booting worker with pid: 286
3542020-01-11 18:50:03 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: starting Scout checker
3552020-01-11 18:50:03 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: starting event watcher
3562020-01-11 18:50:05 AMBASSADOR INFO diagd running
3572020-01-11 18:50:05 AMBASSADOR INFO launching worker process 'watt': 'watt' '--port' '8002' '--notify' 'python /ambassador/post_update.py --watt ' '-s' 'service' '-s' 'ingresses' '-s' 'AuthService' '-s' 'Mapping' '-s' 'Module' '-s' 'RateLimitService' '-s' 'TCPMapping' '-s' 'TLSContext' '-s' 'TracingService' '-s' 'ConsulResolver' '-s' 'KubernetesEndpointResolver' '-s' 'KubernetesServiceResolver' '-s' 'LogService' '--watch' '/ambassador/watch_hook.py'
3582020-01-11 18:50:05 AMBASSADOR INFO watt is PID 295
3592020/01/11 18:50:05 starting watt...
3602020/01/11 18:50:05 kubebootstrap: starting
3612020/01/11 18:50:05 consulwatchman: starting
3622020/01/11 18:50:05 kubewatchman: starting
3632020/01/11 18:50:05 aggregator: starting
3642020/01/11 18:50:05 invoker: starting
3652020/01/11 18:50:05 api: starting
3662020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "service" in namespace "*"
3672020/01/11 18:50:05 api: snapshot server listening on: :8002
3682020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "ingresses" in namespace "*"
3692020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "AuthService" in namespace "*"
3702020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "Mapping" in namespace "*"
3712020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "Module" in namespace "*"
3722020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "RateLimitService" in namespace "*"
3732020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "TCPMapping" in namespace "*"
3742020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "TLSContext" in namespace "*"
3752020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "TracingService" in namespace "*"
3762020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "ConsulResolver" in namespace "*"
3772020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "KubernetesEndpointResolver" in namespace "*"
3782020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "KubernetesServiceResolver" in namespace "*"
3792020/01/11 18:50:05 kubebootstrap: adding kubernetes watch for "LogService" in namespace "*"
3802020/01/11 18:50:05 kubebootstrap: found 0 "TracingService" in namespace "*"
3812020/01/11 18:50:05 kubebootstrap: sent "TracingService" to 1 receivers
3822020/01/11 18:50:05 kubebootstrap: found 0 "ingresses" in namespace "*"
3832020/01/11 18:50:05 kubebootstrap: sent "ingresses" to 1 receivers
3842020/01/11 18:50:05 kubebootstrap: found 1 "Mapping" in namespace "*"
3852020/01/11 18:50:05 kubebootstrap: sent "Mapping" to 1 receivers
3862020/01/11 18:50:05 kubebootstrap: found 0 "TLSContext" in namespace "*"
3872020/01/11 18:50:05 kubebootstrap: sent "TLSContext" to 1 receivers
3882020/01/11 18:50:05 kubebootstrap: found 0 "RateLimitService" in namespace "*"
3892020/01/11 18:50:05 kubebootstrap: sent "RateLimitService" to 1 receivers
3902020/01/11 18:50:05 kubebootstrap: found 0 "TCPMapping" in namespace "*"
3912020/01/11 18:50:05 kubebootstrap: sent "TCPMapping" to 1 receivers
3922020/01/11 18:50:05 kubebootstrap: found 0 "ConsulResolver" in namespace "*"
3932020/01/11 18:50:05 kubebootstrap: sent "ConsulResolver" to 1 receivers
3942020/01/11 18:50:05 kubebootstrap: found 0 "KubernetesEndpointResolver" in namespace "*"
3952020/01/11 18:50:05 kubebootstrap: sent "KubernetesEndpointResolver" to 1 receivers
3962020/01/11 18:50:05 kubebootstrap: found 0 "KubernetesServiceResolver" in namespace "*"
3972020/01/11 18:50:05 kubebootstrap: sent "KubernetesServiceResolver" to 1 receivers
3982020/01/11 18:50:05 kubebootstrap: found 8 "service" in namespace "*"
3992020/01/11 18:50:05 kubebootstrap: sent "service" to 1 receivers
4002020/01/11 18:50:05 kubebootstrap: found 0 "AuthService" in namespace "*"
4012020/01/11 18:50:05 kubebootstrap: sent "AuthService" to 1 receivers
4022020/01/11 18:50:05 kubebootstrap: found 0 "Module" in namespace "*"
4032020/01/11 18:50:05 kubebootstrap: sent "Module" to 1 receivers
4042020/01/11 18:50:05 kubebootstrap: found 0 "LogService" in namespace "*"
4052020/01/11 18:50:05 kubebootstrap: sent "LogService" to 1 receivers
4062020/01/11 18:50:06 aggregator: watch hook stderr: 2020-01-11 18:50:06 watch-hook INFO: YAML: using C dumper
4072020/01/11 18:50:06 aggregator: watch hook stderr:
4082020/01/11 18:50:06 aggregator: found 0 kubernetes watches
4092020/01/11 18:50:06 aggregator: found 0 consul watches
4102020/01/11 18:50:06 aggregator: bootstrapped!
4112020/01/11 18:50:06 kubewatchman: processing 0 kubernetes watch specs
4122020/01/11 18:50:06 consulwatchman: processing 0 consul watches
4132020/01/11 18:50:06 notify: python /ambassador/post_update.py --watt http://localhost:8002/snapshots/1
4142020-01-11 18:50:06 diagd 0.86.1 [P286TThreadPoolExecutor-0_0] INFO: Update requested: watt, http://localhost:8002/snapshots/1
4152020-01-11 18:50:06 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: copying configuration: watt, http://localhost:8002/snapshots/1 to /ambassador/snapshots/snapshot-tmp.yaml
4162020-01-11 18:50:06 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: YAML: using C dumper
4172020-01-11 18:50:06 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: V2Listener: Using log_format 'ACCESS [%START_TIME%] "%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% "%REQ(X-FORWARDED-FOR)%" "%REQ(USER-AGENT)%" "%REQ(X-REQUEST-ID)%" "%REQ(:AUTHORITY)%" "%UPSTREAM_HOST%"
418'
4192020-01-11 18:50:06 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: successfully validated the resulting envoy configuration, continuing...
4202020-01-11 18:50:06 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: saving Envoy configuration for snapshot 1
4212020-01-11 18:50:06 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: running 'kill -HUP 1'
4222020-01-11 18:50:06 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: configuration updated from snapshot 1
4232020-01-11 18:50:06 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: starting Envoy status updater
4242020-01-11 18:50:06 AMBASSADOR INFO launching worker process 'envoy': 'envoy' '-c' '/ambassador/bootstrap-ads.json'
4252020-01-11 18:50:06 AMBASSADOR INFO envoy is PID 345
4262020-01-11 18:50:06 AMBASSADOR INFO KICK: started Envoy as PID 345
427time="2020-01-11T18:50:06Z" level=info msg="Loaded file /ambassador/envoy/envoy.json"
428time="2020-01-11T18:50:06Z" level=info msg="Pushing snapshot v1"
429[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:249] initializing epoch 0 (hot restart version=11.104)
430[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:251] statically linked extensions:
431[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:253] access_loggers: envoy.file_access_log,envoy.http_grpc_access_log,envoy.tcp_grpc_access_log
432[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:256] filters.http: envoy.buffer,envoy.cors,envoy.csrf,envoy.ext_authz,envoy.fault,envoy.filters.http.adaptive_concurrency,envoy.filters.http.dynamic_forward_proxy,envoy.filters.http.grpc_http1_reverse_bridge,envoy.filters.http.grpc_stats,envoy.filters.http.header_to_metadata,envoy.filters.http.jwt_authn,envoy.filters.http.original_src,envoy.filters.http.rbac,envoy.filters.http.tap,envoy.grpc_http1_bridge,envoy.grpc_json_transcoder,envoy.grpc_web,envoy.gzip,envoy.health_check,envoy.http_dynamo_filter,envoy.ip_tagging,envoy.lua,envoy.rate_limit,envoy.router,envoy.squash
433[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:259] filters.listener: envoy.listener.http_inspector,envoy.listener.original_dst,envoy.listener.original_src,envoy.listener.proxy_protocol,envoy.listener.tls_inspector
434[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:262] filters.network: envoy.client_ssl_auth,envoy.echo,envoy.ext_authz,envoy.filters.network.dubbo_proxy,envoy.filters.network.mysql_proxy,envoy.filters.network.rbac,envoy.filters.network.sni_cluster,envoy.filters.network.thrift_proxy,envoy.filters.network.zookeeper_proxy,envoy.http_connection_manager,envoy.mongo_proxy,envoy.ratelimit,envoy.redis_proxy,envoy.tcp_proxy
435[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:264] stat_sinks: envoy.dog_statsd,envoy.metrics_service,envoy.stat_sinks.hystrix,envoy.statsd
436[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:266] tracers: envoy.dynamic.ot,envoy.lightstep,envoy.tracers.datadog,envoy.tracers.opencensus,envoy.tracers.xray,envoy.zipkin
437[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:269] transport_sockets.downstream: envoy.transport_sockets.alts,envoy.transport_sockets.raw_buffer,envoy.transport_sockets.tap,envoy.transport_sockets.tls,raw_buffer,tls
438[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:272] transport_sockets.upstream: envoy.transport_sockets.alts,envoy.transport_sockets.raw_buffer,envoy.transport_sockets.tap,envoy.transport_sockets.tls,raw_buffer,tls
439[2020-01-11 18:50:06.211][345][info][main] [source/server/server.cc:278] buffer implementation: new
440[2020-01-11 18:50:06.213][345][info][main] [source/server/server.cc:344] admin address: 127.0.0.1:8001
441[2020-01-11 18:50:06.214][345][info][main] [source/server/server.cc:458] runtime: layers:
442 - name: base
443 static_layer:
444 {}
445 - name: admin
446 admin_layer:
447 {}
448[2020-01-11 18:50:06.214][345][info][config] [source/server/configuration_impl.cc:62] loading 0 static secret(s)
449[2020-01-11 18:50:06.214][345][info][config] [source/server/configuration_impl.cc:68] loading 1 cluster(s)
450[2020-01-11 18:50:06.214][345][info][upstream] [source/common/upstream/cluster_manager_impl.cc:157] cm init: initializing cds
451[2020-01-11 18:50:06.214][345][info][config] [source/server/configuration_impl.cc:72] loading 0 listener(s)
452[2020-01-11 18:50:06.214][345][info][config] [source/server/configuration_impl.cc:97] loading tracing configuration
453[2020-01-11 18:50:06.214][345][info][config] [source/server/configuration_impl.cc:117] loading stats sink configuration
454[2020-01-11 18:50:06.214][345][info][main] [source/server/server.cc:549] starting main dispatch loop
455[2020-01-11 18:50:06.215][345][info][upstream] [source/common/upstream/cds_api_impl.cc:67] cds: add 2 cluster(s), remove 1 cluster(s)
456[2020-01-11 18:50:06.216][345][info][upstream] [source/common/upstream/cds_api_impl.cc:83] cds: add/update cluster 'cluster_127_0_0_1_8877'
457[2020-01-11 18:50:06.216][345][info][upstream] [source/common/upstream/cds_api_impl.cc:83] cds: add/update cluster 'cluster_hello_default'
458[2020-01-11 18:50:06.216][345][info][upstream] [source/common/upstream/cluster_manager_impl.cc:161] cm init: all clusters initialized
459[2020-01-11 18:50:06.216][345][info][main] [source/server/server.cc:528] all clusters initialized. initializing init manager
460[2020-01-11 18:50:06.217][345][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.Filter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
461[2020-01-11 18:50:06.217][345][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.config.filter.accesslog.v2.AccessLog.config' from file accesslog.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
462[2020-01-11 18:50:06.218][345][info][upstream] [source/server/lds_api.cc:63] lds: add/update listener 'ambassador-listener-8080'
463[2020-01-11 18:50:06.218][345][info][config] [source/server/listener_manager_impl.cc:578] all dependencies initialized. starting workers
4642020-01-11 18:50:06 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: Scout reports {"latest_version": "0.86.1", "application": "ambassador", "cached": false, "timestamp": 1578768606.803745}
4652020-01-11 18:50:06 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: Scout notices: []
466ACCESS [2020-01-11T18:50:30.834Z] "GET /hello/ HTTP/1.1" 200 - 0 14 2 1 "172.26.0.1" "curl/7.58.0" "eb0b0899-6694-4573-92d7-9f036b5e8dd2" "172.26.0.3" "10.43.207.150:80"
467
4682020/01/11 18:50:43 kubebootstrap: found 1 "TLSContext" in namespace "*"
4692020/01/11 18:50:43 kubebootstrap: sent "TLSContext" to 1 receivers
4702020/01/11 18:50:44 aggregator: watch hook stderr: 2020-01-11 18:50:44 watch-hook INFO: YAML: using C dumper
4712020/01/11 18:50:44 aggregator: watch hook stderr: 2020-01-11 18:50:44 watch-hook INFO: resolve_secret tls-cert, namespace default: namespacing is True
4722020/01/11 18:50:44 aggregator: watch hook stderr: 2020-01-11 18:50:44 watch-hook INFO: resolve_secret tls-cert.default: asking handler to load
4732020/01/11 18:50:44 aggregator: watch hook stderr: 2020-01-11 18:50:44 watch-hook INFO: SecretRecorder: Trying to load secret tls-cert in namespace default from TLSContext <IRTLSContext tls.default.1>
4742020/01/11 18:50:44 aggregator: watch hook stderr: 2020-01-11 18:50:44 watch-hook INFO: resolve_secret tls-cert.default: asking handler to cache
4752020/01/11 18:50:44 aggregator: watch hook stderr:
4762020/01/11 18:50:44 aggregator: found 1 kubernetes watches
4772020/01/11 18:50:44 aggregator: found 0 consul watches
4782020/01/11 18:50:44 kubewatchman: processing 1 kubernetes watch specs
4792020/01/11 18:50:44 kubewatchman: add kubernetes watcher kubernetes:secret|default|metadata.name=tls-cert|*
4802020/01/11 18:50:44 kubernetes:secret|default|metadata.name=tls-cert|*: starting
4812020/01/11 18:50:44 consulwatchman: processing 0 consul watches
4822020/01/11 18:50:44 notify: python /ambassador/post_update.py --watt http://localhost:8002/snapshots/2
4832020/01/11 18:50:44 kubernetes:secret|default|metadata.name=tls-cert|*: found 1 "secret" in namespace "default"
4842020/01/11 18:50:44 kubernetes:secret|default|metadata.name=tls-cert|*: sent "secret" to receivers
4852020-01-11 18:50:44 diagd 0.86.1 [P286TThreadPoolExecutor-0_0] INFO: Update requested: watt, http://localhost:8002/snapshots/2
4862020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: copying configuration: watt, http://localhost:8002/snapshots/2 to /ambassador/snapshots/snapshot-tmp.yaml
4872020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert, namespace default: namespacing is True
4882020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert.default: asking handler to load
4892020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] ERROR: Secret tls-cert.default unknown
4902020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] ERROR: tls.default.1: <RichStatus BAD error=TLSContext tls found no certificate in secret tls-cert in namespace default, ignoring... hostname=ambassador-55648bc7d5-pjvfn version=0.86.1>
4912020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: V2Listener: Using log_format 'ACCESS [%START_TIME%] "%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% "%REQ(X-FORWARDED-FOR)%" "%REQ(USER-AGENT)%" "%REQ(X-REQUEST-ID)%" "%REQ(:AUTHORITY)%" "%UPSTREAM_HOST%"
492'
4932020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: successfully validated the resulting envoy configuration, continuing...
4942020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: saving Envoy configuration for snapshot 2
4952020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: running 'kill -HUP 1'
4962020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: configuration updated from snapshot 2
4972020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: error tls.default.1 TLSContext tls found no certificate in secret tls-cert in namespace default, ignoring...
4982020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: Scout reports {"latest_version": "0.86.1", "application": "ambassador", "cached": true, "timestamp": 1578768606.19856}
4992020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: Scout notices: [{"level": "DEBUG", "message": "Returning cached result"}]
500time="2020-01-11T18:50:44Z" level=info msg="Loaded file /ambassador/envoy/envoy.json"
501time="2020-01-11T18:50:44Z" level=info msg="Pushing snapshot v2"
502[2020-01-11 18:50:44.273][345][info][upstream] [source/common/upstream/cds_api_impl.cc:67] cds: add 2 cluster(s), remove 1 cluster(s)
503[2020-01-11 18:50:44.274][345][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.Filter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
5042020/01/11 18:50:44 aggregator: watch hook stderr: 2020-01-11 18:50:44 watch-hook INFO: YAML: using C dumper
5052020/01/11 18:50:44 aggregator: watch hook stderr: 2020-01-11 18:50:44 watch-hook INFO: resolve_secret tls-cert, namespace default: namespacing is True
5062020/01/11 18:50:44 aggregator: watch hook stderr: 2020-01-11 18:50:44 watch-hook INFO: resolve_secret tls-cert.default: asking handler to load
5072020/01/11 18:50:44 aggregator: watch hook stderr: 2020-01-11 18:50:44 watch-hook INFO: SecretRecorder: Trying to load secret tls-cert in namespace default from TLSContext <IRTLSContext tls.default.1>
5082020/01/11 18:50:44 aggregator: watch hook stderr: 2020-01-11 18:50:44 watch-hook INFO: resolve_secret tls-cert.default: asking handler to cache
5092020/01/11 18:50:44 aggregator: watch hook stderr:
5102020/01/11 18:50:44 aggregator: found 1 kubernetes watches
5112020/01/11 18:50:44 aggregator: found 0 consul watches
5122020/01/11 18:50:44 kubewatchman: processing 1 kubernetes watch specs
5132020/01/11 18:50:44 consulwatchman: processing 0 consul watches
5142020/01/11 18:50:44 notify: python /ambassador/post_update.py --watt http://localhost:8002/snapshots/3
5152020-01-11 18:50:44 diagd 0.86.1 [P286TThreadPoolExecutor-0_10] INFO: Update requested: watt, http://localhost:8002/snapshots/3
5162020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: copying configuration: watt, http://localhost:8002/snapshots/3 to /ambassador/snapshots/snapshot-tmp.yaml
5172020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert, namespace default: namespacing is True
5182020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert.default: found secret_info
5192020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert.default: asking handler to cache
5202020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: V2Listener: Using log_format 'ACCESS [%START_TIME%] "%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% "%REQ(X-FORWARDED-FOR)%" "%REQ(USER-AGENT)%" "%REQ(X-REQUEST-ID)%" "%REQ(:AUTHORITY)%" "%UPSTREAM_HOST%"
521'
5222020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: V2Listener: SNI (1) route check tls, ['*'], {
523 "common_tls_context": {
524 "tls_certificates": [
525 {
526 "certificate_chain": {
527 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.crt"
528 },
529 "private_key": {
530 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.key"
531 }
532 }
533 ]
534 }
535}
5362020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: successfully validated the resulting envoy configuration, continuing...
5372020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: saving Envoy configuration for snapshot 3
5382020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: running 'kill -HUP 1'
5392020-01-11 18:50:44 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: configuration updated from snapshot 3
540time="2020-01-11T18:50:44Z" level=info msg="Loaded file /ambassador/envoy/envoy.json"
541time="2020-01-11T18:50:44Z" level=info msg="Pushing snapshot v3"
542[2020-01-11 18:50:44.604][345][info][upstream] [source/common/upstream/cds_api_impl.cc:67] cds: add 2 cluster(s), remove 1 cluster(s)
543[2020-01-11 18:50:44.604][345][info][upstream] [source/server/lds_api.cc:46] lds: remove listener 'ambassador-listener-8080'
544[2020-01-11 18:50:44.604][345][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.FilterChain.tls_context' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
545[2020-01-11 18:50:44.604][345][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.Filter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
546[2020-01-11 18:50:44.605][345][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.config.filter.accesslog.v2.AccessLog.config' from file accesslog.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
547[2020-01-11 18:50:44.608][345][info][upstream] [source/server/lds_api.cc:63] lds: add/update listener 'ambassador-listener-8443'
5482020-01-11 18:50:45 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: Scout reports {"latest_version": "0.86.1", "application": "ambassador", "cached": false, "timestamp": 1578768645.225615}
5492020-01-11 18:50:45 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: Scout notices: []
550ACCESS [2020-01-11T18:50:56.840Z] "GET /hello/ HTTP/1.1" 200 - 0 14 1 1 "172.26.0.1" "curl/7.58.0" "e18a5685-e5f0-413b-8333-f6311a53cd1b" "172.26.0.3" "10.43.207.150:80"
551
5522020/01/11 18:51:19 kubebootstrap: found 9 "service" in namespace "*"
5532020/01/11 18:51:19 kubebootstrap: sent "service" to 1 receivers
5542020/01/11 18:51:19 kubebootstrap: found 10 "service" in namespace "*"
5552020/01/11 18:51:19 aggregator: watch hook stderr: 2020-01-11 18:51:19 watch-hook INFO: YAML: using C dumper
5562020/01/11 18:51:19 aggregator: watch hook stderr: 2020-01-11 18:51:19 watch-hook INFO: resolve_secret tls-cert, namespace default: namespacing is True
5572020/01/11 18:51:19 aggregator: watch hook stderr: 2020-01-11 18:51:19 watch-hook INFO: resolve_secret tls-cert.default: asking handler to load
5582020/01/11 18:51:19 aggregator: watch hook stderr: 2020-01-11 18:51:19 watch-hook INFO: SecretRecorder: Trying to load secret tls-cert in namespace default from TLSContext <IRTLSContext tls.default.1>
5592020/01/11 18:51:19 aggregator: watch hook stderr: 2020-01-11 18:51:19 watch-hook INFO: resolve_secret tls-cert.default: asking handler to cache
5602020/01/11 18:51:19 aggregator: watch hook stderr:
5612020/01/11 18:51:19 aggregator: found 1 kubernetes watches
5622020/01/11 18:51:19 aggregator: found 0 consul watches
5632020/01/11 18:51:19 kubewatchman: processing 1 kubernetes watch specs
5642020/01/11 18:51:19 consulwatchman: processing 0 consul watches
5652020/01/11 18:51:19 notify: python /ambassador/post_update.py --watt http://localhost:8002/snapshots/4
5662020/01/11 18:51:19 kubebootstrap: sent "service" to 1 receivers
5672020-01-11 18:51:19 diagd 0.86.1 [P286TThreadPoolExecutor-0_28] INFO: Update requested: watt, http://localhost:8002/snapshots/4
5682020-01-11 18:51:19 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: copying configuration: watt, http://localhost:8002/snapshots/4 to /ambassador/snapshots/snapshot-tmp.yaml
5692020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert, namespace default: namespacing is True
5702020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert.default: found secret_info
5712020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert.default: asking handler to cache
5722020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: V2Listener: Using log_format 'ACCESS [%START_TIME%] "%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% "%REQ(X-FORWARDED-FOR)%" "%REQ(USER-AGENT)%" "%REQ(X-REQUEST-ID)%" "%REQ(:AUTHORITY)%" "%UPSTREAM_HOST%"
573'
5742020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: V2Listener: SNI (1) route check tls, ['*'], {
575 "common_tls_context": {
576 "tls_certificates": [
577 {
578 "certificate_chain": {
579 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.crt"
580 },
581 "private_key": {
582 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.key"
583 }
584 }
585 ]
586 }
587}
5882020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: successfully validated the resulting envoy configuration, continuing...
5892020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: saving Envoy configuration for snapshot 4
5902020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: running 'kill -HUP 1'
5912020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: configuration updated from snapshot 4
5922020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: Scout reports {"latest_version": "0.86.1", "application": "ambassador", "cached": true, "timestamp": 1578768644.598488}
5932020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: Scout notices: [{"level": "DEBUG", "message": "Returning cached result"}]
594time="2020-01-11T18:51:20Z" level=info msg="Loaded file /ambassador/envoy/envoy.json"
595time="2020-01-11T18:51:20Z" level=info msg="Pushing snapshot v4"
596[2020-01-11 18:51:20.045][345][info][upstream] [source/common/upstream/cds_api_impl.cc:67] cds: add 2 cluster(s), remove 1 cluster(s)
597[2020-01-11 18:51:20.045][345][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.FilterChain.tls_context' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
598[2020-01-11 18:51:20.045][345][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.Filter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
5992020/01/11 18:51:20 aggregator: watch hook stderr: 2020-01-11 18:51:20 watch-hook INFO: YAML: using C dumper
6002020/01/11 18:51:20 aggregator: watch hook stderr: 2020-01-11 18:51:20 watch-hook INFO: resolve_secret tls-cert, namespace default: namespacing is True
6012020/01/11 18:51:20 aggregator: watch hook stderr: 2020-01-11 18:51:20 watch-hook INFO: resolve_secret tls-cert.default: asking handler to load
6022020/01/11 18:51:20 aggregator: watch hook stderr: 2020-01-11 18:51:20 watch-hook INFO: SecretRecorder: Trying to load secret tls-cert in namespace default from TLSContext <IRTLSContext tls.default.1>
6032020/01/11 18:51:20 aggregator: watch hook stderr: 2020-01-11 18:51:20 watch-hook INFO: resolve_secret tls-cert.default: asking handler to cache
6042020/01/11 18:51:20 aggregator: watch hook stderr:
6052020/01/11 18:51:20 aggregator: found 1 kubernetes watches
6062020/01/11 18:51:20 aggregator: found 0 consul watches
6072020/01/11 18:51:20 kubewatchman: processing 1 kubernetes watch specs
6082020/01/11 18:51:20 consulwatchman: processing 0 consul watches
6092020/01/11 18:51:20 notify: python /ambassador/post_update.py --watt http://localhost:8002/snapshots/5
6102020-01-11 18:51:20 diagd 0.86.1 [P286TThreadPoolExecutor-0_3] INFO: Update requested: watt, http://localhost:8002/snapshots/5
6112020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: copying configuration: watt, http://localhost:8002/snapshots/5 to /ambassador/snapshots/snapshot-tmp.yaml
6122020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert, namespace default: namespacing is True
6132020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert.default: found secret_info
6142020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: resolve_secret tls-cert.default: asking handler to cache
6152020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: V2Listener: Using log_format 'ACCESS [%START_TIME%] "%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% "%REQ(X-FORWARDED-FOR)%" "%REQ(USER-AGENT)%" "%REQ(X-REQUEST-ID)%" "%REQ(:AUTHORITY)%" "%UPSTREAM_HOST%"
616'
6172020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: V2Listener: SNI (1) route check tls, ['*'], {
618 "common_tls_context": {
619 "tls_certificates": [
620 {
621 "certificate_chain": {
622 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.crt"
623 },
624 "private_key": {
625 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.key"
626 }
627 }
628 ]
629 }
630}
6312020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: successfully validated the resulting envoy configuration, continuing...
6322020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: saving Envoy configuration for snapshot 5
6332020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: running 'kill -HUP 1'
6342020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: configuration updated from snapshot 5
6352020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: Scout reports {"latest_version": "0.86.1", "application": "ambassador", "cached": true, "timestamp": 1578768644.598488}
6362020-01-11 18:51:20 diagd 0.86.1 [P286TAmbassadorEventWatcher] INFO: Scout notices: [{"level": "DEBUG", "message": "Returning cached result"}]
637time="2020-01-11T18:51:20Z" level=info msg="Loaded file /ambassador/envoy/envoy.json"
638time="2020-01-11T18:51:20Z" level=info msg="Pushing snapshot v5"
639[2020-01-11 18:51:20.352][345][info][upstream] [source/common/upstream/cds_api_impl.cc:67] cds: add 2 cluster(s), remove 1 cluster(s)
640[2020-01-11 18:51:20.352][345][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.FilterChain.tls_context' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
641[2020-01-11 18:51:20.352][345][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.Filter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
642ACCESS [2020-01-11T18:53:14.492Z] "GET /hello/ HTTP/1.1" 200 - 0 14 1 1 "172.26.0.1" "curl/7.58.0" "0a93a457-a697-4e09-8527-a6c9cc41d659" "172.26.0.3" "10.43.207.150:80"
643
644
645 "denominator": "HUNDRED",
646 "numerator": 100
647 },
648 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
649 }
650 },
651 "route": {
652 "cluster": "cluster_127_0_0_1_8500_default",
653 "prefix_rewrite": "/edge_stack_ui/edge_stack/",
654 "priority": null,
655 "timeout": "60.000s"
656 }
657}...
6582020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
6592020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
6602020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
661 "match": {
662 "case_sensitive": true,
663 "prefix": "/ambassador/v0/check_ready",
664 "runtime_fraction": {
665 "default_value": {
666 "denominator": "HUNDRED",
667 "numerator": 100
668 },
669 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
670 }
671 },
672 "route": {
673 "cluster": "cluster_127_0_0_1_8877_default",
674 "prefix_rewrite": "/ambassador/v0/check_ready",
675 "priority": null,
676 "timeout": "10.000s"
677 }
678}...
6792020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
6802020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
6812020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
682 "match": {
683 "case_sensitive": true,
684 "prefix": "/ambassador/v0/check_alive",
685 "runtime_fraction": {
686 "default_value": {
687 "denominator": "HUNDRED",
688 "numerator": 100
689 },
690 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
691 }
692 },
693 "route": {
694 "cluster": "cluster_127_0_0_1_8877_default",
695 "prefix_rewrite": "/ambassador/v0/check_alive",
696 "priority": null,
697 "timeout": "10.000s"
698 }
699}...
7002020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
7012020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
7022020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
703 "match": {
704 "case_sensitive": true,
705 "prefix": "/ambassador/v0/",
706 "runtime_fraction": {
707 "default_value": {
708 "denominator": "HUNDRED",
709 "numerator": 100
710 },
711 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
712 }
713 },
714 "route": {
715 "cluster": "cluster_127_0_0_1_8877_default",
716 "prefix_rewrite": "/ambassador/v0/",
717 "priority": null,
718 "timeout": "10.000s"
719 }
720}...
7212020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
7222020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
7232020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
724 "match": {
725 "case_sensitive": true,
726 "prefix": "/hello/",
727 "runtime_fraction": {
728 "default_value": {
729 "denominator": "HUNDRED",
730 "numerator": 100
731 },
732 "runtime_key": "routing.traffic_shift.cluster_hello_default_default"
733 }
734 },
735 "route": {
736 "cluster": "cluster_hello_default_default",
737 "prefix_rewrite": "/",
738 "priority": null,
739 "timeout": "3.000s"
740 }
741}...
7422020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
7432020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
7442020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
745 "_precedence": -1000000,
746 "match": {
747 "case_sensitive": true,
748 "prefix": "/",
749 "runtime_fraction": {
750 "default_value": {
751 "denominator": "HUNDRED",
752 "numerator": 100
753 },
754 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
755 }
756 },
757 "route": {
758 "cluster": "cluster_127_0_0_1_8500_default",
759 "prefix_rewrite": "/edge_stack_ui/",
760 "priority": null,
761 "timeout": "60.000s"
762 }
763}...
7642020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: force Route for fallback Mapping
7652020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
7662020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: ==== ENVOY LISTENERS ====: [
767 {
768 "address": {
769 "socket_address": {
770 "address": "0.0.0.0",
771 "port_value": 8443,
772 "protocol": "TCP"
773 }
774 },
775 "filter_chains": [
776 {
777 "filter_chain_match": {
778 "transport_protocol": "tls"
779 },
780 "filters": [
781 {
782 "config": {
783 "access_log": [
784 {
785 "config": {
786 "format": "ACCESS [%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% \"%REQ(X-FORWARDED-FOR)%\" \"%REQ(USER-AGENT)%\" \"%REQ(X-REQUEST-ID)%\" \"%REQ(:AUTHORITY)%\" \"%UPSTREAM_HOST%\"\n",
787 "path": "/dev/fd/1"
788 },
789 "name": "envoy.file_access_log"
790 }
791 ],
792 "http_filters": [
793 {
794 "name": "envoy.cors"
795 },
796 {
797 "name": "envoy.router"
798 }
799 ],
800 "http_protocol_options": {
801 "accept_http_10": false
802 },
803 "normalize_path": true,
804 "route_config": {
805 "virtual_hosts": [
806 {
807 "domains": [
808 "*"
809 ],
810 "name": "ambassador-listener-8443-*",
811 "routes": [
812 {
813 "match": {
814 "case_sensitive": true,
815 "headers": [
816 {
817 "exact_match": "https",
818 "name": "x-forwarded-proto"
819 }
820 ],
821 "prefix": "/.ambassador/",
822 "runtime_fraction": {
823 "default_value": {
824 "denominator": "HUNDRED",
825 "numerator": 100
826 },
827 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
828 }
829 },
830 "route": {
831 "cluster": "cluster_127_0_0_1_8500_default",
832 "priority": null,
833 "timeout": "3.000s"
834 }
835 },
836 {
837 "match": {
838 "case_sensitive": true,
839 "prefix": "/.ambassador/",
840 "runtime_fraction": {
841 "default_value": {
842 "denominator": "HUNDRED",
843 "numerator": 100
844 },
845 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
846 }
847 },
848 "route": {
849 "cluster": "cluster_127_0_0_1_8500_default",
850 "priority": null,
851 "timeout": "3.000s"
852 }
853 },
854 {
855 "match": {
856 "case_sensitive": true,
857 "headers": [
858 {
859 "exact_match": "https",
860 "name": "x-forwarded-proto"
861 }
862 ],
863 "prefix": "/edge_stack/",
864 "runtime_fraction": {
865 "default_value": {
866 "denominator": "HUNDRED",
867 "numerator": 100
868 },
869 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
870 }
871 },
872 "route": {
873 "cluster": "cluster_127_0_0_1_8500_default",
874 "prefix_rewrite": "/edge_stack_ui/edge_stack/",
875 "priority": null,
876 "timeout": "60.000s"
877 }
878 },
879 {
880 "match": {
881 "case_sensitive": true,
882 "prefix": "/edge_stack/",
883 "runtime_fraction": {
884 "default_value": {
885 "denominator": "HUNDRED",
886 "numerator": 100
887 },
888 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
889 }
890 },
891 "route": {
892 "cluster": "cluster_127_0_0_1_8500_default",
893 "prefix_rewrite": "/edge_stack_ui/edge_stack/",
894 "priority": null,
895 "timeout": "60.000s"
896 }
897 },
898 {
899 "match": {
900 "case_sensitive": true,
901 "headers": [
902 {
903 "exact_match": "https",
904 "name": "x-forwarded-proto"
905 }
906 ],
907 "prefix": "/ambassador/v0/check_ready",
908 "runtime_fraction": {
909 "default_value": {
910 "denominator": "HUNDRED",
911 "numerator": 100
912 },
913 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
914 }
915 },
916 "route": {
917 "cluster": "cluster_127_0_0_1_8877_default",
918 "prefix_rewrite": "/ambassador/v0/check_ready",
919 "priority": null,
920 "timeout": "10.000s"
921 }
922 },
923 {
924 "match": {
925 "case_sensitive": true,
926 "prefix": "/ambassador/v0/check_ready",
927 "runtime_fraction": {
928 "default_value": {
929 "denominator": "HUNDRED",
930 "numerator": 100
931 },
932 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
933 }
934 },
935 "route": {
936 "cluster": "cluster_127_0_0_1_8877_default",
937 "prefix_rewrite": "/ambassador/v0/check_ready",
938 "priority": null,
939 "timeout": "10.000s"
940 }
941 },
942 {
943 "match": {
944 "case_sensitive": true,
945 "headers": [
946 {
947 "exact_match": "https",
948 "name": "x-forwarded-proto"
949 }
950 ],
951 "prefix": "/ambassador/v0/check_alive",
952 "runtime_fraction": {
953 "default_value": {
954 "denominator": "HUNDRED",
955 "numerator": 100
956 },
957 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
958 }
959 },
960 "route": {
961 "cluster": "cluster_127_0_0_1_8877_default",
962 "prefix_rewrite": "/ambassador/v0/check_alive",
963 "priority": null,
964 "timeout": "10.000s"
965 }
966 },
967 {
968 "match": {
969 "case_sensitive": true,
970 "prefix": "/ambassador/v0/check_alive",
971 "runtime_fraction": {
972 "default_value": {
973 "denominator": "HUNDRED",
974 "numerator": 100
975 },
976 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
977 }
978 },
979 "route": {
980 "cluster": "cluster_127_0_0_1_8877_default",
981 "prefix_rewrite": "/ambassador/v0/check_alive",
982 "priority": null,
983 "timeout": "10.000s"
984 }
985 },
986 {
987 "match": {
988 "case_sensitive": true,
989 "headers": [
990 {
991 "exact_match": "https",
992 "name": "x-forwarded-proto"
993 }
994 ],
995 "prefix": "/ambassador/v0/",
996 "runtime_fraction": {
997 "default_value": {
998 "denominator": "HUNDRED",
999 "numerator": 100
1000 },
1001 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1002 }
1003 },
1004 "route": {
1005 "cluster": "cluster_127_0_0_1_8877_default",
1006 "prefix_rewrite": "/ambassador/v0/",
1007 "priority": null,
1008 "timeout": "10.000s"
1009 }
1010 },
1011 {
1012 "match": {
1013 "case_sensitive": true,
1014 "prefix": "/ambassador/v0/",
1015 "runtime_fraction": {
1016 "default_value": {
1017 "denominator": "HUNDRED",
1018 "numerator": 100
1019 },
1020 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1021 }
1022 },
1023 "route": {
1024 "cluster": "cluster_127_0_0_1_8877_default",
1025 "prefix_rewrite": "/ambassador/v0/",
1026 "priority": null,
1027 "timeout": "10.000s"
1028 }
1029 },
1030 {
1031 "match": {
1032 "case_sensitive": true,
1033 "headers": [
1034 {
1035 "exact_match": "https",
1036 "name": "x-forwarded-proto"
1037 }
1038 ],
1039 "prefix": "/hello/",
1040 "runtime_fraction": {
1041 "default_value": {
1042 "denominator": "HUNDRED",
1043 "numerator": 100
1044 },
1045 "runtime_key": "routing.traffic_shift.cluster_hello_default_default"
1046 }
1047 },
1048 "route": {
1049 "cluster": "cluster_hello_default_default",
1050 "prefix_rewrite": "/",
1051 "priority": null,
1052 "timeout": "3.000s"
1053 }
1054 },
1055 {
1056 "match": {
1057 "case_sensitive": true,
1058 "prefix": "/hello/",
1059 "runtime_fraction": {
1060 "default_value": {
1061 "denominator": "HUNDRED",
1062 "numerator": 100
1063 },
1064 "runtime_key": "routing.traffic_shift.cluster_hello_default_default"
1065 }
1066 },
1067 "route": {
1068 "cluster": "cluster_hello_default_default",
1069 "prefix_rewrite": "/",
1070 "priority": null,
1071 "timeout": "3.000s"
1072 }
1073 },
1074 {
1075 "match": {
1076 "case_sensitive": true,
1077 "prefix": "/",
1078 "runtime_fraction": {
1079 "default_value": {
1080 "denominator": "HUNDRED",
1081 "numerator": 100
1082 },
1083 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1084 }
1085 },
1086 "route": {
1087 "cluster": "cluster_127_0_0_1_8500_default",
1088 "prefix_rewrite": "/edge_stack_ui/",
1089 "priority": null,
1090 "timeout": "60.000s"
1091 }
1092 },
1093 {
1094 "match": {
1095 "case_sensitive": true,
1096 "prefix": "/",
1097 "runtime_fraction": {
1098 "default_value": {
1099 "denominator": "HUNDRED",
1100 "numerator": 100
1101 },
1102 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1103 }
1104 },
1105 "route": {
1106 "cluster": "cluster_127_0_0_1_8500_default",
1107 "prefix_rewrite": "/edge_stack_ui/",
1108 "priority": null,
1109 "timeout": "60.000s"
1110 }
1111 }
1112 ]
1113 }
1114 ]
1115 },
1116 "server_name": "envoy",
1117 "stat_prefix": "ingress_http",
1118 "use_remote_address": true,
1119 "xff_num_trusted_hops": 0
1120 },
1121 "name": "envoy.http_connection_manager"
1122 }
1123 ],
1124 "tls_context": {
1125 "common_tls_context": {
1126 "tls_certificates": [
1127 {
1128 "certificate_chain": {
1129 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.crt"
1130 },
1131 "private_key": {
1132 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.key"
1133 }
1134 }
1135 ]
1136 }
1137 },
1138 "use_proxy_proto": false
1139 }
1140 ],
1141 "listener_filters": [
1142 {
1143 "config": {},
1144 "name": "envoy.listener.tls_inspector"
1145 }
1146 ],
1147 "name": "ambassador-listener-8443"
1148 }
1149]
11502020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: successfully validated the resulting envoy configuration, continuing...
11512020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: saving Envoy configuration for snapshot 1
11522020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: running 'kill -HUP 1'
1153KubeStatus MASTER 303: mark_live Mapping/ambassador-edge-stack.default
1154KubeStatus MASTER 303: mark_live Mapping/edgestack-direct-mapping.default
1155KubeStatus MASTER 303: mark_live Mapping/edgestack-fallback-mapping.default
1156KubeStatus MASTER 303: mark_live Mapping/hello.default
11572020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: K8s status update: Mapping ambassador-edge-stack.default, {"state": "Running"}...
1158KubeStatus MASTER 303: Mapping/ambassador-edge-stack.default needs {"state": "Running"}
11592020-01-11 18:52:28 AMBASSADOR INFO launching worker process 'envoy': 'envoy' '-c' '/ambassador/bootstrap-ads.json'
11602020-01-11 18:52:28 AMBASSADOR INFO envoy is PID 404
11612020-01-11 18:52:28 AMBASSADOR INFO KICK: started Envoy as PID 404
11622020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: K8s status update: Mapping edgestack-direct-mapping.default, {"state": "Running"}...
1163KubeStatus MASTER 303: Mapping/edgestack-direct-mapping.default needs {"state": "Running"}
1164KubeStatus UPDATE 403: running command: ['kubestatus', 'Mapping', '-f', 'metadata.name=ambassador-edge-stack', '-n', 'default', '-u', '/dev/fd/0']
11652020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: K8s status update: Mapping edgestack-fallback-mapping.default, {"state": "Running"}...
1166KubeStatus MASTER 303: Mapping/edgestack-fallback-mapping.default needs {"state": "Running"}
11672020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: K8s status update: Mapping hello.default, {"state": "Running"}...
1168KubeStatus UPDATE 406: running command: ['kubestatus', 'Mapping', '-f', 'metadata.name=edgestack-direct-mapping', '-n', 'default', '-u', '/dev/fd/0']
1169KubeStatus MASTER 303: Mapping/hello.default needs {"state": "Running"}
11702020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: configuration updated from snapshot 1
1171KubeStatus UPDATE 408: running command: ['kubestatus', 'Mapping', '-f', 'metadata.name=edgestack-fallback-mapping', '-n', 'default', '-u', '/dev/fd/0']
11722020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: starting Envoy status updater
1173KubeStatus UPDATE 409: running command: ['kubestatus', 'Mapping', '-f', 'metadata.name=hello', '-n', 'default', '-u', '/dev/fd/0']
11742020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: error Ambassador could not find the Host CRD definition. Please visit https://www.getambassador.io/reference/core/crds/ for more information. You can continue using Ambassador via Kubernetes annotations, any configuration via CRDs will be ignored...
11752020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: Scout reports {"latest_version": "1.0.0", "cached": false, "timestamp": 1578768748.582728}
11762020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: Scout notices: []
11772020/01/11 18:52:28 notify: Traceback (most recent call last):
11782020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/urllib3/connection.py", line 159, in _new_conn
1179time="2020-01-11T18:52:28Z" level=info msg="Loaded file /ambassador/envoy/envoy.json"
11802020/01/11 18:52:28 notify: (self._dns_host, self.port), self.timeout, **extra_kw)
11812020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/urllib3/util/connection.py", line 80, in create_connection
11822020/01/11 18:52:28 notify: raise err
11832020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/urllib3/util/connection.py", line 70, in create_connection
11842020/01/11 18:52:28 notify: sock.connect(sa)
11852020/01/11 18:52:28 notify: ConnectionRefusedError: [Errno 111] Connection refused
11862020/01/11 18:52:28 notify:
11872020/01/11 18:52:28 notify: During handling of the above exception, another exception occurred:
11882020/01/11 18:52:28 notify:
11892020/01/11 18:52:28 notify: Traceback (most recent call last):
11902020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/urllib3/connectionpool.py", line 600, in urlopen
11912020/01/11 18:52:28 notify: chunked=chunked)
11922020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/urllib3/connectionpool.py", line 354, in _make_request
11932020/01/11 18:52:28 notify: conn.request(method, url, **httplib_request_kw)
11942020/01/11 18:52:28 notify: File "/usr/lib/python3.7/http/client.py", line 1252, in request
1195[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:249] initializing epoch 0 (hot restart version=11.104)
1196[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:251] statically linked extensions:
1197[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:253] access_loggers: envoy.file_access_log,envoy.http_grpc_access_log,envoy.tcp_grpc_access_log
1198[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:256] filters.http: envoy.buffer,envoy.cors,envoy.csrf,envoy.ext_authz,envoy.fault,envoy.filters.http.adaptive_concurrency,envoy.filters.http.dynamic_forward_proxy,envoy.filters.http.grpc_http1_reverse_bridge,envoy.filters.http.grpc_stats,envoy.filters.http.header_to_metadata,envoy.filters.http.jwt_authn,envoy.filters.http.original_src,envoy.filters.http.rbac,envoy.filters.http.tap,envoy.grpc_http1_bridge,envoy.grpc_json_transcoder,envoy.grpc_web,envoy.gzip,envoy.health_check,envoy.http_dynamo_filter,envoy.ip_tagging,envoy.lua,envoy.rate_limit,envoy.router,envoy.squash
1199[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:259] filters.listener: envoy.listener.http_inspector,envoy.listener.original_dst,envoy.listener.original_src,envoy.listener.proxy_protocol,envoy.listener.tls_inspector
1200[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:262] filters.network: envoy.client_ssl_auth,envoy.echo,envoy.ext_authz,envoy.filters.network.dubbo_proxy,envoy.filters.network.mysql_proxy,envoy.filters.network.rbac,envoy.filters.network.sni_cluster,envoy.filters.network.thrift_proxy,envoy.filters.network.zookeeper_proxy,envoy.http_connection_manager,envoy.mongo_proxy,envoy.ratelimit,envoy.redis_proxy,envoy.tcp_proxy
1201[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:264] stat_sinks: envoy.dog_statsd,envoy.metrics_service,envoy.stat_sinks.hystrix,envoy.statsd
1202[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:266] tracers: envoy.dynamic.ot,envoy.lightstep,envoy.tracers.datadog,envoy.tracers.opencensus,envoy.tracers.xray,envoy.zipkin
1203[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:269] transport_sockets.downstream: envoy.transport_sockets.alts,envoy.transport_sockets.raw_buffer,envoy.transport_sockets.tap,envoy.transport_sockets.tls,raw_buffer,tls
1204[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:272] transport_sockets.upstream: envoy.transport_sockets.alts,envoy.transport_sockets.raw_buffer,envoy.transport_sockets.tap,envoy.transport_sockets.tls,raw_buffer,tls
1205[2020-01-11 18:52:28.587][404][info][main] [source/server/server.cc:278] buffer implementation: new
12062020/01/11 18:52:28 notify: self._send_request(method, url, body, headers, encode_chunked)
12072020/01/11 18:52:28 notify: File "/usr/lib/python3.7/http/client.py", line 1298, in _send_request
12082020/01/11 18:52:28 notify: self.endheaders(body, encode_chunked=encode_chunked)
12092020/01/11 18:52:28 notify: File "/usr/lib/python3.7/http/client.py", line 1247, in endheaders
1210[2020-01-11 18:52:28.588][404][info][main] [source/server/server.cc:344] admin address: 127.0.0.1:8001
12112020/01/11 18:52:28 notify: self._send_output(message_body, encode_chunked=encode_chunked)
12122020/01/11 18:52:28 notify: File "/usr/lib/python3.7/http/client.py", line 1026, in _send_output
1213[2020-01-11 18:52:28.589][404][info][main] [source/server/server.cc:458] runtime: layers:
1214 - name: base
1215 static_layer:
1216 {}
1217 - name: admin
1218 admin_layer:
1219 {}
1220[2020-01-11 18:52:28.589][404][info][config] [source/server/configuration_impl.cc:62] loading 0 static secret(s)
1221[2020-01-11 18:52:28.589][404][info][config] [source/server/configuration_impl.cc:68] loading 1 cluster(s)
12222020/01/11 18:52:28 notify: self.send(msg)
12232020/01/11 18:52:28 notify: File "/usr/lib/python3.7/http/client.py", line 966, in send
12242020/01/11 18:52:28 notify: self.connect()
12252020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/urllib3/connection.py", line 181, in connect
12262020/01/11 18:52:28 notify: conn = self._new_conn()
1227[2020-01-11 18:52:28.589][404][info][upstream] [source/common/upstream/cluster_manager_impl.cc:157] cm init: initializing cds
12282020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/urllib3/connection.py", line 168, in _new_conn
12292020/01/11 18:52:28 notify: self, "Failed to establish a new connection: %s" % e)
12302020/01/11 18:52:28 notify: urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPConnection object at 0x7f4683655e90>: Failed to establish a new connection: [Errno 111] Connection refused
12312020/01/11 18:52:28 notify:
12322020/01/11 18:52:28 notify: During handling of the above exception, another exception occurred:
12332020/01/11 18:52:28 notify:
12342020/01/11 18:52:28 notify: Traceback (most recent call last):
12352020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/requests/adapters.py", line 449, in send
12362020/01/11 18:52:28 notify: timeout=timeout
12372020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/urllib3/connectionpool.py", line 638, in urlopen
1238[2020-01-11 18:52:28.590][404][info][config] [source/server/configuration_impl.cc:72] loading 0 listener(s)
1239[2020-01-11 18:52:28.590][404][info][config] [source/server/configuration_impl.cc:97] loading tracing configuration
1240[2020-01-11 18:52:28.590][404][info][config] [source/server/configuration_impl.cc:117] loading stats sink configuration
1241[2020-01-11 18:52:28.590][404][info][main] [source/server/server.cc:549] starting main dispatch loop
12422020/01/11 18:52:28 notify: _stacktrace=sys.exc_info()[2])
12432020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/urllib3/util/retry.py", line 399, in increment
12442020/01/11 18:52:28 notify: raise MaxRetryError(_pool, url, error or ResponseError(cause))
12452020/01/11 18:52:28 notify: urllib3.exceptions.MaxRetryError: HTTPConnectionPool(host='localhost', port=8500): Max retries exceeded with url: /_internal/v0/watt?url=http%3A%2F%2Flocalhost%3A8002%2Fsnapshots%2F1 (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f4683655e90>: Failed to establish a new connection: [Errno 111] Connection refused'))
12462020/01/11 18:52:28 notify:
12472020/01/11 18:52:28 notify: During handling of the above exception, another exception occurred:
12482020/01/11 18:52:28 notify:
12492020/01/11 18:52:28 notify: Traceback (most recent call last):
12502020/01/11 18:52:28 notify: File "/ambassador/post_update.py", line 50, in <module>
12512020/01/11 18:52:28 notify: r = requests.post(url, params={ arg_key: args[0] })
12522020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/requests/api.py", line 116, in post
12532020/01/11 18:52:28 notify: return request('post', url, data=data, json=json, **kwargs)
12542020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/requests/api.py", line 60, in request
12552020/01/11 18:52:28 notify: return session.request(method=method, url=url, **kwargs)
12562020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/requests/sessions.py", line 533, in request
12572020/01/11 18:52:28 notify: resp = self.send(prep, **send_kwargs)
12582020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/requests/sessions.py", line 646, in send
12592020/01/11 18:52:28 notify: r = adapter.send(request, **kwargs)
12602020/01/11 18:52:28 notify: File "/usr/lib/python3.7/site-packages/requests/adapters.py", line 516, in send
12612020/01/11 18:52:28 notify: raise ConnectionError(e, request=request)
12622020/01/11 18:52:28 notify: requests.exceptions.ConnectionError: HTTPConnectionPool(host='localhost', port=8500): Max retries exceeded with url: /_internal/v0/watt?url=http%3A%2F%2Flocalhost%3A8002%2Fsnapshots%2F1 (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f4683655e90>: Failed to establish a new connection: [Errno 111] Connection refused'))
1263[2020-01-11 18:52:28.591][404][info][upstream] [source/common/upstream/cds_api_impl.cc:67] cds: add 0 cluster(s), remove 1 cluster(s)
1264[2020-01-11 18:52:28.591][404][info][upstream] [source/common/upstream/cluster_manager_impl.cc:161] cm init: all clusters initialized
1265[2020-01-11 18:52:28.591][404][info][main] [source/server/server.cc:528] all clusters initialized. initializing init manager
1266[2020-01-11 18:52:28.591][404][info][config] [source/server/listener_manager_impl.cc:578] all dependencies initialized. starting workers
1267time="2020-01-11T18:52:28Z" level=info msg="Pushing snapshot v1"
1268[2020-01-11 18:52:28.595][404][info][upstream] [source/common/upstream/cds_api_impl.cc:67] cds: add 3 cluster(s), remove 1 cluster(s)
1269[2020-01-11 18:52:28.596][404][info][upstream] [source/common/upstream/cds_api_impl.cc:83] cds: add/update cluster 'cluster_127_0_0_1_8500_default'
1270[2020-01-11 18:52:28.597][404][info][upstream] [source/common/upstream/cds_api_impl.cc:83] cds: add/update cluster 'cluster_127_0_0_1_8877_default'
1271[2020-01-11 18:52:28.597][404][info][upstream] [source/common/upstream/cds_api_impl.cc:83] cds: add/update cluster 'cluster_hello_default_default'
1272[2020-01-11 18:52:28.598][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.FilterChain.tls_context' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
1273[2020-01-11 18:52:28.598][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.Filter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
1274[2020-01-11 18:52:28.598][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.ListenerFilter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
1275[2020-01-11 18:52:28.600][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.config.filter.accesslog.v2.AccessLog.config' from file accesslog.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
12762020/01/11 18:52:28 notify: exit status 1
1277[2020-01-11 18:52:28.601][404][warning][config] [source/common/config/grpc_mux_subscription_impl.cc:82] gRPC config for type.googleapis.com/envoy.api.v2.Listener rejected: Error adding/updating listener(s) ambassador-listener-8443: route: unknown cluster 'cluster_hello_default_default'
1278[2020-01-11 18:52:28.602][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.FilterChain.tls_context' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
1279[2020-01-11 18:52:28.602][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.Filter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
1280[2020-01-11 18:52:28.602][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.ListenerFilter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
1281[2020-01-11 18:52:28.603][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.config.filter.accesslog.v2.AccessLog.config' from file accesslog.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
1282[2020-01-11 18:52:28.605][404][info][upstream] [source/server/lds_api.cc:63] lds: add/update listener 'ambassador-listener-8443'
1283Updating hello.default
12842020/01/11 18:52:28 error updating resource: mappings.getambassador.io "hello" not found
1285KubeStatus DONE 303: result edgestack-fallback-mapping.default: update OK
1286KubeStatus DONE 303: result edgestack-direct-mapping.default: update OK
1287KubeStatus DONE 303: result ambassador-edge-stack.default: update OK
1288KubeStatus DONE 303: result hello.default: update OK
1289time="2020-01-11 18:52:28" level=warning msg="statsd is not in use"
1290time="2020-01-11 18:52:28" level=info msg="Iteration started request " subsystem=fetcher
1291time="2020-01-11 18:52:28" level=debug msg="HTTP GET" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
12922020-01-11 18:52:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_5] INFO: 61CB9121-3978-4C8D-B0FB-7F54D0C0641A: 127.0.0.1 "GET /ambassador/v0/diag/" START
12932020-01-11 18:52:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_5] ERROR: could not get banner_content: HTTPConnectionPool(host='127.0.0.1', port=8500): Max retries exceeded with url: /banner (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7f03cceb3e50>: Failed to establish a new connection: [Errno 111] Connection refused'))
12942020-01-11 18:52:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_5] INFO: DEBUG_MODE False
1295status_dict {'CRDs': {'status': False, 'specifics': [(False, 'Core CRD type definitions are missing')]}, 'Error check': {'status': False, 'specifics': [(False, '1 total error logged')]}, 'TLS': {'status': True, 'specifics': [(True, '1 TLSContext is active')]}, 'Mappings': {'status': True, 'specifics': [(True, '4 Mappings are active')]}}
12962020-01-11 18:52:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_5] INFO: 61CB9121-3978-4C8D-B0FB-7F54D0C0641A: 127.0.0.1 "GET /ambassador/v0/diag/" 11ms 200 success
1297time="2020-01-11 18:52:28" level=debug msg="GET succeeded" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
1298time="2020-01-11 18:52:28" level=info msg="Found mapping" baseURL="https://ambassador.default.svc.cluster.local" name=hello namespace=default prefix=/hello subsystem=fetcher
1299time="2020-01-11 18:52:28" level=debug msg="HTTP GET" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
1300ACCESS [2020-01-11T18:52:28.730Z] "GET /hello/.ambassador-internal/openapi-docs HTTP/1.1" 404 - 0 232 10 9 "10.42.0.10" "Go-http-client/1.1" "2c00092a-0920-40d3-87ec-f8c90378c564" "127.0.0.1:8443" "10.43.207.150:80"
1301time="2020-01-11 18:52:28" level=error msg="Bad HTTP response" status_code=404 subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
1302time="2020-01-11 18:52:28" level=error msg="HTTP error 404 from https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
1303time="2020-01-11 18:52:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=ambassador-edge-stack name=ambassador-edge-stack namespace=default prefix=/.ambassador rewrite= subsystem=fetcher
1304time="2020-01-11 18:52:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-fallback-mapping name=edgestack-fallback-mapping namespace=default prefix= rewrite=/edge_stack_ui/ subsystem=fetcher
1305time="2020-01-11 18:52:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-direct-mapping name=edgestack-direct-mapping namespace=default prefix=/edge_stack rewrite=/edge_stack_ui/edge_stack/ subsystem=fetcher
1306time="2020-01-11 18:52:28" level=info msg="Iteration done" subsystem=fetcher
13072020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: reading edge-stack-mappings.yaml (/ambassador/init-config/edge-stack-mappings.yaml)
13082020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: YAML: using C parser
13092020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: YAML: using C dumper
13102020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook ERROR: -global-: <RichStatus BAD error=Ambassador could not find the Host CRD definition. Please visit https://www.getambassador.io/reference/core/crds/ for more information. You can continue using Ambassador via Kubernetes annotations, any configuration via CRDs will be ignored... hostname=aes-69bbd5db9c-rwgcx version=1.0.0>
13112020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: dropping K8s dup TLSContext/tls.default
13122020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook ERROR: ERROR ERROR ERROR Starting with configuration errors
13132020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: IRTLSContext setup good: {
13142020/01/11 18:52:28 aggregator: watch hook stderr: "_active": false,
13152020/01/11 18:52:28 aggregator: watch hook stderr: "_errored": false,
13162020/01/11 18:52:28 aggregator: watch hook stderr: "_rkey": "tls.default.1",
13172020/01/11 18:52:28 aggregator: watch hook stderr: "hosts": [
13182020/01/11 18:52:28 aggregator: watch hook stderr: "*"
13192020/01/11 18:52:28 aggregator: watch hook stderr: ],
13202020/01/11 18:52:28 aggregator: watch hook stderr: "is_fallback": false,
13212020/01/11 18:52:28 aggregator: watch hook stderr: "kind": "TLSContext",
13222020/01/11 18:52:28 aggregator: watch hook stderr: "location": "tls.default.1",
13232020/01/11 18:52:28 aggregator: watch hook stderr: "metadata_labels": {
13242020/01/11 18:52:28 aggregator: watch hook stderr: "ambassador_crd": "tls.default"
13252020/01/11 18:52:28 aggregator: watch hook stderr: },
13262020/01/11 18:52:28 aggregator: watch hook stderr: "name": "tls",
13272020/01/11 18:52:28 aggregator: watch hook stderr: "namespace": "default",
13282020/01/11 18:52:28 aggregator: watch hook stderr: "secret_info": {
13292020/01/11 18:52:28 aggregator: watch hook stderr: "secret": "tls-cert"
13302020/01/11 18:52:28 aggregator: watch hook stderr: }
13312020/01/11 18:52:28 aggregator: watch hook stderr: }
13322020/01/11 18:52:28 aggregator: watch hook stderr: 2020-01-11 18:52:28 watch-hook INFO: IR: watching Edge Stack; wizard allowed
13332020/01/11 18:52:28 aggregator: watch hook stderr:
13342020/01/11 18:52:28 aggregator: found 2 kubernetes watches
13352020/01/11 18:52:28 aggregator: found 0 consul watches
13362020/01/11 18:52:28 kubewatchman: processing 2 kubernetes watch specs
13372020/01/11 18:52:28 consulwatchman: processing 0 consul watches
13382020/01/11 18:52:28 notify: python /ambassador/post_update.py --watt http://localhost:8002/snapshots/2
13392020-01-11 18:52:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_2] INFO: Update requested: watt, http://localhost:8002/snapshots/2
13402020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: copying configuration: watt, http://localhost:8002/snapshots/2 to /ambassador/snapshots/snapshot-tmp.yaml
13412020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: reading edge-stack-mappings.yaml (/ambassador/init-config/edge-stack-mappings.yaml)
13422020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] ERROR: -global-: <RichStatus BAD error=Ambassador could not find the Host CRD definition. Please visit https://www.getambassador.io/reference/core/crds/ for more information. You can continue using Ambassador via Kubernetes annotations, any configuration via CRDs will be ignored... hostname=aes-69bbd5db9c-rwgcx version=1.0.0>
13432020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: dropping K8s dup TLSContext/tls.default
13442020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] ERROR: ERROR ERROR ERROR Starting with configuration errors
13452020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: IRTLSContext setup good: {
1346 "_active": false,
1347 "_errored": false,
1348 "_rkey": "tls.default.1",
1349 "hosts": [
1350 "*"
1351 ],
1352 "is_fallback": false,
1353 "kind": "TLSContext",
1354 "location": "tls.default.1",
1355 "metadata_labels": {
1356 "ambassador_crd": "tls.default"
1357 },
1358 "name": "tls",
1359 "namespace": "default",
1360 "secret_info": {
1361 "secret": "tls-cert"
1362 }
1363}
13642020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: IR: starting Edge Stack; wizard allowed
13652020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: ListenerFactory: AT START
13662020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: listeners: {}
13672020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: unused_contexts: {
1368 "*": "<IRTLSContext tls: hosts ['*'] secret tls-cert>"
1369}
13702020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: ListenerFactory: AFTER HOSTS
13712020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: listeners: {}
13722020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: unused_contexts: {
1373 "*": "<IRTLSContext tls: hosts ['*'] secret tls-cert>"
1374}
13752020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: ListenerFactory: AFTER CONTEXTS
13762020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: listeners: {
1377 "*": "<Listener ir.listener for *:8443, ctx tls, secure Route, insecure Reject/None>"
1378}
13792020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: unused_contexts: {}
13802020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: ListenerFactory: AFTER FALLBACK
13812020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: listeners: {
1382 "*": "<Listener ir.listener for *:8443, ctx tls, secure Route, insecure Reject/None>"
1383}
13842020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: unused_contexts: {}
13852020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: working on <Listener ir.listener for *:8443, ctx tls, secure Route, insecure Reject/None>
13862020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listener ambassador-listener-8443 created
13872020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listener: Using log_format 'ACCESS [%START_TIME%] "%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% "%REQ(X-FORWARDED-FOR)%" "%REQ(USER-AGENT)%" "%REQ(X-REQUEST-ID)%" "%REQ(:AUTHORITY)%" "%UPSTREAM_HOST%"'
13882020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listener ambassador-listener-8443: adding VHost * for host *, secure Route, insecure Reject)
13892020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: distinct domain count 1, global SNI disabled
13902020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: {
1391 "8443": {
1392 "address": {
1393 "socket_address": {
1394 "address": "0.0.0.0",
1395 "port_value": 8443,
1396 "protocol": "TCP"
1397 }
1398 },
1399 "name": "ambassador-listener-8443",
1400 "vhosts": {
1401 "*": {
1402 "_action": "Route",
1403 "_hostname": "*",
1404 "_insecure_action": "Reject",
1405 "_needs_redirect": false,
1406 "_secure": true,
1407 "routes": [],
1408 "tls_context": {
1409 "common_tls_context": {
1410 "tls_certificates": [
1411 {
1412 "certificate_chain": {
1413 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.crt"
1414 },
1415 "private_key": {
1416 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.key"
1417 }
1418 }
1419 ]
1420 }
1421 },
1422 "use_proxy_proto": false
1423 }
1424 }
1425 }
1426}
14272020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
1428 "_precedence": 1000000,
1429 "match": {
1430 "case_sensitive": true,
1431 "prefix": "/.ambassador/",
1432 "runtime_fraction": {
1433 "default_value": {
1434 "denominator": "HUNDRED",
1435 "numerator": 100
1436 },
1437 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1438 }
1439 },
1440 "route": {
1441 "cluster": "cluster_127_0_0_1_8500_default",
1442 "priority": null,
1443 "timeout": "3.000s"
1444 }
1445}...
14462020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
14472020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
14482020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
1449 "_precedence": 1000000,
1450 "match": {
1451 "case_sensitive": true,
1452 "prefix": "/edge_stack/",
1453 "runtime_fraction": {
1454 "default_value": {
1455 "denominator": "HUNDRED",
1456 "numerator": 100
1457 },
1458 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1459 }
1460 },
1461 "route": {
1462 "cluster": "cluster_127_0_0_1_8500_default",
1463 "prefix_rewrite": "/edge_stack_ui/edge_stack/",
1464 "priority": null,
1465 "timeout": "60.000s"
1466 }
1467}...
14682020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
14692020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
14702020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
1471 "match": {
1472 "case_sensitive": true,
1473 "prefix": "/ambassador/v0/check_ready",
1474 "runtime_fraction": {
1475 "default_value": {
1476 "denominator": "HUNDRED",
1477 "numerator": 100
1478 },
1479 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1480 }
1481 },
1482 "route": {
1483 "cluster": "cluster_127_0_0_1_8877_default",
1484 "prefix_rewrite": "/ambassador/v0/check_ready",
1485 "priority": null,
1486 "timeout": "10.000s"
1487 }
1488}...
14892020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
14902020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
14912020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
1492 "match": {
1493 "case_sensitive": true,
1494 "prefix": "/ambassador/v0/check_alive",
1495 "runtime_fraction": {
1496 "default_value": {
1497 "denominator": "HUNDRED",
1498 "numerator": 100
1499 },
1500 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1501 }
1502 },
1503 "route": {
1504 "cluster": "cluster_127_0_0_1_8877_default",
1505 "prefix_rewrite": "/ambassador/v0/check_alive",
1506 "priority": null,
1507 "timeout": "10.000s"
1508 }
1509}...
15102020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
15112020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
15122020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
1513 "match": {
1514 "case_sensitive": true,
1515 "prefix": "/ambassador/v0/",
1516 "runtime_fraction": {
1517 "default_value": {
1518 "denominator": "HUNDRED",
1519 "numerator": 100
1520 },
1521 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1522 }
1523 },
1524 "route": {
1525 "cluster": "cluster_127_0_0_1_8877_default",
1526 "prefix_rewrite": "/ambassador/v0/",
1527 "priority": null,
1528 "timeout": "10.000s"
1529 }
1530}...
15312020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
15322020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
15332020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
1534 "match": {
1535 "case_sensitive": true,
1536 "prefix": "/hello/",
1537 "runtime_fraction": {
1538 "default_value": {
1539 "denominator": "HUNDRED",
1540 "numerator": 100
1541 },
1542 "runtime_key": "routing.traffic_shift.cluster_hello_default_default"
1543 }
1544 },
1545 "route": {
1546 "cluster": "cluster_hello_default_default",
1547 "prefix_rewrite": "/",
1548 "priority": null,
1549 "timeout": "3.000s"
1550 }
1551}...
15522020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: Accept as Route
15532020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
15542020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: route {
1555 "_precedence": -1000000,
1556 "match": {
1557 "case_sensitive": true,
1558 "prefix": "/",
1559 "runtime_fraction": {
1560 "default_value": {
1561 "denominator": "HUNDRED",
1562 "numerator": 100
1563 },
1564 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1565 }
1566 },
1567 "route": {
1568 "cluster": "cluster_127_0_0_1_8500_default",
1569 "prefix_rewrite": "/edge_stack_ui/",
1570 "priority": null,
1571 "timeout": "60.000s"
1572 }
1573}...
15742020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * secure: force Route for fallback Mapping
15752020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: V2Listeners: ambassador-listener-8443 * insecure: Drop due to Reject action
15762020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: ==== ENVOY LISTENERS ====: [
1577 {
1578 "address": {
1579 "socket_address": {
1580 "address": "0.0.0.0",
1581 "port_value": 8443,
1582 "protocol": "TCP"
1583 }
1584 },
1585 "filter_chains": [
1586 {
1587 "filter_chain_match": {
1588 "transport_protocol": "tls"
1589 },
1590 "filters": [
1591 {
1592 "config": {
1593 "access_log": [
1594 {
1595 "config": {
1596 "format": "ACCESS [%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" %RESPONSE_CODE% %RESPONSE_FLAGS% %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% \"%REQ(X-FORWARDED-FOR)%\" \"%REQ(USER-AGENT)%\" \"%REQ(X-REQUEST-ID)%\" \"%REQ(:AUTHORITY)%\" \"%UPSTREAM_HOST%\"\n",
1597 "path": "/dev/fd/1"
1598 },
1599 "name": "envoy.file_access_log"
1600 }
1601 ],
1602 "http_filters": [
1603 {
1604 "name": "envoy.cors"
1605 },
1606 {
1607 "name": "envoy.router"
1608 }
1609 ],
1610 "http_protocol_options": {
1611 "accept_http_10": false
1612 },
1613 "normalize_path": true,
1614 "route_config": {
1615 "virtual_hosts": [
1616 {
1617 "domains": [
1618 "*"
1619 ],
1620 "name": "ambassador-listener-8443-*",
1621 "routes": [
1622 {
1623 "match": {
1624 "case_sensitive": true,
1625 "headers": [
1626 {
1627 "exact_match": "https",
1628 "name": "x-forwarded-proto"
1629 }
1630 ],
1631 "prefix": "/.ambassador/",
1632 "runtime_fraction": {
1633 "default_value": {
1634 "denominator": "HUNDRED",
1635 "numerator": 100
1636 },
1637 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1638 }
1639 },
1640 "route": {
1641 "cluster": "cluster_127_0_0_1_8500_default",
1642 "priority": null,
1643 "timeout": "3.000s"
1644 }
1645 },
1646 {
1647 "match": {
1648 "case_sensitive": true,
1649 "prefix": "/.ambassador/",
1650 "runtime_fraction": {
1651 "default_value": {
1652 "denominator": "HUNDRED",
1653 "numerator": 100
1654 },
1655 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1656 }
1657 },
1658 "route": {
1659 "cluster": "cluster_127_0_0_1_8500_default",
1660 "priority": null,
1661 "timeout": "3.000s"
1662 }
1663 },
1664 {
1665 "match": {
1666 "case_sensitive": true,
1667 "headers": [
1668 {
1669 "exact_match": "https",
1670 "name": "x-forwarded-proto"
1671 }
1672 ],
1673 "prefix": "/edge_stack/",
1674 "runtime_fraction": {
1675 "default_value": {
1676 "denominator": "HUNDRED",
1677 "numerator": 100
1678 },
1679 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1680 }
1681 },
1682 "route": {
1683 "cluster": "cluster_127_0_0_1_8500_default",
1684 "prefix_rewrite": "/edge_stack_ui/edge_stack/",
1685 "priority": null,
1686 "timeout": "60.000s"
1687 }
1688 },
1689 {
1690 "match": {
1691 "case_sensitive": true,
1692 "prefix": "/edge_stack/",
1693 "runtime_fraction": {
1694 "default_value": {
1695 "denominator": "HUNDRED",
1696 "numerator": 100
1697 },
1698 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1699 }
1700 },
1701 "route": {
1702 "cluster": "cluster_127_0_0_1_8500_default",
1703 "prefix_rewrite": "/edge_stack_ui/edge_stack/",
1704 "priority": null,
1705 "timeout": "60.000s"
1706 }
1707 },
1708 {
1709 "match": {
1710 "case_sensitive": true,
1711 "headers": [
1712 {
1713 "exact_match": "https",
1714 "name": "x-forwarded-proto"
1715 }
1716 ],
1717 "prefix": "/ambassador/v0/check_ready",
1718 "runtime_fraction": {
1719 "default_value": {
1720 "denominator": "HUNDRED",
1721 "numerator": 100
1722 },
1723 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1724 }
1725 },
1726 "route": {
1727 "cluster": "cluster_127_0_0_1_8877_default",
1728 "prefix_rewrite": "/ambassador/v0/check_ready",
1729 "priority": null,
1730 "timeout": "10.000s"
1731 }
1732 },
1733 {
1734 "match": {
1735 "case_sensitive": true,
1736 "prefix": "/ambassador/v0/check_ready",
1737 "runtime_fraction": {
1738 "default_value": {
1739 "denominator": "HUNDRED",
1740 "numerator": 100
1741 },
1742 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1743 }
1744 },
1745 "route": {
1746 "cluster": "cluster_127_0_0_1_8877_default",
1747 "prefix_rewrite": "/ambassador/v0/check_ready",
1748 "priority": null,
1749 "timeout": "10.000s"
1750 }
1751 },
1752 {
1753 "match": {
1754 "case_sensitive": true,
1755 "headers": [
1756 {
1757 "exact_match": "https",
1758 "name": "x-forwarded-proto"
1759 }
1760 ],
1761 "prefix": "/ambassador/v0/check_alive",
1762 "runtime_fraction": {
1763 "default_value": {
1764 "denominator": "HUNDRED",
1765 "numerator": 100
1766 },
1767 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1768 }
1769 },
1770 "route": {
1771 "cluster": "cluster_127_0_0_1_8877_default",
1772 "prefix_rewrite": "/ambassador/v0/check_alive",
1773 "priority": null,
1774 "timeout": "10.000s"
1775 }
1776 },
1777 {
1778 "match": {
1779 "case_sensitive": true,
1780 "prefix": "/ambassador/v0/check_alive",
1781 "runtime_fraction": {
1782 "default_value": {
1783 "denominator": "HUNDRED",
1784 "numerator": 100
1785 },
1786 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1787 }
1788 },
1789 "route": {
1790 "cluster": "cluster_127_0_0_1_8877_default",
1791 "prefix_rewrite": "/ambassador/v0/check_alive",
1792 "priority": null,
1793 "timeout": "10.000s"
1794 }
1795 },
1796 {
1797 "match": {
1798 "case_sensitive": true,
1799 "headers": [
1800 {
1801 "exact_match": "https",
1802 "name": "x-forwarded-proto"
1803 }
1804 ],
1805 "prefix": "/ambassador/v0/",
1806 "runtime_fraction": {
1807 "default_value": {
1808 "denominator": "HUNDRED",
1809 "numerator": 100
1810 },
1811 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1812 }
1813 },
1814 "route": {
1815 "cluster": "cluster_127_0_0_1_8877_default",
1816 "prefix_rewrite": "/ambassador/v0/",
1817 "priority": null,
1818 "timeout": "10.000s"
1819 }
1820 },
1821 {
1822 "match": {
1823 "case_sensitive": true,
1824 "prefix": "/ambassador/v0/",
1825 "runtime_fraction": {
1826 "default_value": {
1827 "denominator": "HUNDRED",
1828 "numerator": 100
1829 },
1830 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8877_default"
1831 }
1832 },
1833 "route": {
1834 "cluster": "cluster_127_0_0_1_8877_default",
1835 "prefix_rewrite": "/ambassador/v0/",
1836 "priority": null,
1837 "timeout": "10.000s"
1838 }
1839 },
1840 {
1841 "match": {
1842 "case_sensitive": true,
1843 "headers": [
1844 {
1845 "exact_match": "https",
1846 "name": "x-forwarded-proto"
1847 }
1848 ],
1849 "prefix": "/hello/",
1850 "runtime_fraction": {
1851 "default_value": {
1852 "denominator": "HUNDRED",
1853 "numerator": 100
1854 },
1855 "runtime_key": "routing.traffic_shift.cluster_hello_default_default"
1856 }
1857 },
1858 "route": {
1859 "cluster": "cluster_hello_default_default",
1860 "prefix_rewrite": "/",
1861 "priority": null,
1862 "timeout": "3.000s"
1863 }
1864 },
1865 {
1866 "match": {
1867 "case_sensitive": true,
1868 "prefix": "/hello/",
1869 "runtime_fraction": {
1870 "default_value": {
1871 "denominator": "HUNDRED",
1872 "numerator": 100
1873 },
1874 "runtime_key": "routing.traffic_shift.cluster_hello_default_default"
1875 }
1876 },
1877 "route": {
1878 "cluster": "cluster_hello_default_default",
1879 "prefix_rewrite": "/",
1880 "priority": null,
1881 "timeout": "3.000s"
1882 }
1883 },
1884 {
1885 "match": {
1886 "case_sensitive": true,
1887 "prefix": "/",
1888 "runtime_fraction": {
1889 "default_value": {
1890 "denominator": "HUNDRED",
1891 "numerator": 100
1892 },
1893 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1894 }
1895 },
1896 "route": {
1897 "cluster": "cluster_127_0_0_1_8500_default",
1898 "prefix_rewrite": "/edge_stack_ui/",
1899 "priority": null,
1900 "timeout": "60.000s"
1901 }
1902 },
1903 {
1904 "match": {
1905 "case_sensitive": true,
1906 "prefix": "/",
1907 "runtime_fraction": {
1908 "default_value": {
1909 "denominator": "HUNDRED",
1910 "numerator": 100
1911 },
1912 "runtime_key": "routing.traffic_shift.cluster_127_0_0_1_8500_default"
1913 }
1914 },
1915 "route": {
1916 "cluster": "cluster_127_0_0_1_8500_default",
1917 "prefix_rewrite": "/edge_stack_ui/",
1918 "priority": null,
1919 "timeout": "60.000s"
1920 }
1921 }
1922 ]
1923 }
1924 ]
1925 },
1926 "server_name": "envoy",
1927 "stat_prefix": "ingress_http",
1928 "use_remote_address": true,
1929 "xff_num_trusted_hops": 0
1930 },
1931 "name": "envoy.http_connection_manager"
1932 }
1933 ],
1934 "tls_context": {
1935 "common_tls_context": {
1936 "tls_certificates": [
1937 {
1938 "certificate_chain": {
1939 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.crt"
1940 },
1941 "private_key": {
1942 "filename": "/ambassador/snapshots/default/secrets-decoded/tls-cert/4E2B717D1196E81441675151E149744B09F8D29A.key"
1943 }
1944 }
1945 ]
1946 }
1947 },
1948 "use_proxy_proto": false
1949 }
1950 ],
1951 "listener_filters": [
1952 {
1953 "config": {},
1954 "name": "envoy.listener.tls_inspector"
1955 }
1956 ],
1957 "name": "ambassador-listener-8443"
1958 }
1959]
1960time="2020-01-11 18:52:28" level=debug msg="runtime changed. loading new snapshot at /tmp/amb/config/config"
1961time="2020-01-11 18:52:28" level=warning msg="runtime: error processing /tmp/amb/config/config: lstat /tmp/amb/config/config: no such file or directory"
1962time="2020-01-11 18:52:28" level=debug msg="waiting for runtime update"
1963time="2020-01-11 18:52:28" level=debug msg="DEV_WEBUI_PORT=\"\"" MAIN=http
19642020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: successfully validated the resulting envoy configuration, continuing...
19652020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: saving Envoy configuration for snapshot 2
19662020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: running 'kill -HUP 1'
1967KubeStatus MASTER 303: mark_live Mapping/ambassador-edge-stack.default
1968KubeStatus MASTER 303: mark_live Mapping/edgestack-direct-mapping.default
1969KubeStatus MASTER 303: mark_live Mapping/edgestack-fallback-mapping.default
1970KubeStatus MASTER 303: mark_live Mapping/hello.default
19712020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: K8s status update: Mapping ambassador-edge-stack.default, {"state": "Running"}...
1972KubeStatus MASTER 303: Mapping/ambassador-edge-stack.default == {"state": "Running"}
19732020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: K8s status update: Mapping edgestack-direct-mapping.default, {"state": "Running"}...
1974KubeStatus MASTER 303: Mapping/edgestack-direct-mapping.default == {"state": "Running"}
19752020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: K8s status update: Mapping edgestack-fallback-mapping.default, {"state": "Running"}...
1976KubeStatus MASTER 303: Mapping/edgestack-fallback-mapping.default == {"state": "Running"}
19772020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: K8s status update: Mapping hello.default, {"state": "Running"}...
1978KubeStatus MASTER 303: Mapping/hello.default == {"state": "Running"}
19792020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: configuration updated from snapshot 2
19802020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: error Ambassador could not find the Host CRD definition. Please visit https://www.getambassador.io/reference/core/crds/ for more information. You can continue using Ambassador via Kubernetes annotations, any configuration via CRDs will be ignored...
19812020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: Scout reports {"latest_version": "1.0.0", "cached": true, "timestamp": 1578768748.582699}
19822020-01-11 18:52:28 diagd 1.0.0 [P303TAmbassadorEventWatcher] INFO: Scout notices: [{"level": "DEBUG", "message": "Returning cached result"}]
1983time="2020-01-11 18:52:28" level=debug msg="loading WATT snapshot from \"http://localhost:8002/snapshots/2\"" MAIN=http SUB=http-server/handler
1984time="2020-01-11T18:52:28Z" level=info msg="Loaded file /ambassador/envoy/envoy.json"
1985time="2020-01-11 18:52:28" level=debug msg="processing snapshot change..." MAIN=acme_client
1986time="2020-01-11 18:52:28" level=debug msg="rectify: starting" MAIN=acme_client
1987time="2020-01-11 18:52:28" level=debug msg="rectify: Phase 0→1 (Pre-ACME): NA(state=Initial)→DefaultsFilled" MAIN=acme_client
1988time="2020-01-11 18:52:28" level=debug msg="rectify: Phase 1→2 (ACME account pre-registration): DefaultsFilled→ACMEUserPrivateKeyCreated" MAIN=acme_client
1989time="2020-01-11 18:52:28" level=debug msg="rectify: Phase 2→3 (ACME account registration): ACMEUserPrivateKeyCreated→ACMEUserRegistered" MAIN=acme_client
1990time="2020-01-11 18:52:28" level=debug msg="rectify: Phase 3→4→0 (ACME certificate request): ACMEUserRegistered→ACMECertificateChallenge→NA(state=Ready)" MAIN=acme_client
1991time="2020-01-11 18:52:28" level=debug msg="rectify: finished" MAIN=acme_client
1992time="2020-01-11T18:52:28Z" level=info msg="Pushing snapshot v2"
1993[2020-01-11 18:52:28.930][404][info][upstream] [source/common/upstream/cds_api_impl.cc:67] cds: add 3 cluster(s), remove 1 cluster(s)
1994[2020-01-11 18:52:28.931][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.FilterChain.tls_context' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
1995[2020-01-11 18:52:28.931][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.Filter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
1996[2020-01-11 18:52:28.931][404][warning][misc] [source/common/protobuf/utility.cc:282] Using deprecated option 'envoy.api.v2.listener.ListenerFilter.config' from file listener.proto. This configuration will be removed from Envoy soon. Please see https://www.envoyproxy.io/docs/envoy/latest/intro/deprecated for details.
1997time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing counter go.pauseTotalNs: 445612"
1998time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing counter go.totalAlloc: 73405424"
1999time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing counter ratelimit.runtime.load_attempts: 1"
2000time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing counter ratelimit.runtime.load_failures: 1"
2001time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing counter go.mallocs: 497964"
2002time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing counter go.frees: 461226"
2003time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing counter ratelimit.service.config_load_success: 1"
2004time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing counter go.numGC: 5"
2005time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.alloc: 8559432"
2006time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.heapObjects: 36738"
2007time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2008time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.sys: 0"
2009time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.heapIdle: 113926144"
2010time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.heapSys: 131530752"
2011time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.heapInuse: 17604608"
2012time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2013time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.heapAlloc: 8559432"
2014time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.heapReleased: 101228544"
2015time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2016time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2017time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge go.numGoroutine: 79"
2018time="2020-01-11 18:52:38" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2019Calling Metriton
2020SCOUT_DISABLE, enforcing hard-limits
2021time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing counter go.totalAlloc: 17656"
2022time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing counter go.mallocs: 503"
2023time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing counter go.frees: 41"
2024time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.heapSys: 131530752"
2025time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.heapInuse: 17604608"
2026time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2027time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.heapAlloc: 8577088"
2028time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.heapReleased: 113926144"
2029time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2030time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2031time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.numGoroutine: 78"
2032time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2033time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.alloc: 8577088"
2034time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.heapObjects: 37200"
2035time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2036time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.sys: 0"
2037time="2020-01-11 18:52:48" level=debug msg="[gostats] flushing gauge go.heapIdle: 113926144"
2038time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing counter go.totalAlloc: 11888"
2039time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing counter go.mallocs: 364"
2040time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing counter go.frees: 30"
2041time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.heapSys: 131530752"
2042time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.heapInuse: 17604608"
2043time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2044time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.numGoroutine: 78"
2045time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2046time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.heapAlloc: 8588976"
2047time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.heapReleased: 113926144"
2048time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2049time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2050time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.alloc: 8588976"
2051time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.heapObjects: 37534"
2052time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2053time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.sys: 0"
2054time="2020-01-11 18:52:58" level=debug msg="[gostats] flushing gauge go.heapIdle: 113926144"
2055time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing counter go.totalAlloc: 11904"
2056time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing counter go.mallocs: 364"
2057time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing counter go.frees: 29"
2058time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.sys: 0"
2059time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.heapIdle: 113926144"
2060time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.heapSys: 131530752"
2061time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.heapInuse: 17604608"
2062time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2063time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2064time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.heapAlloc: 8600880"
2065time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.heapReleased: 113926144"
2066time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2067time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2068time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.numGoroutine: 78"
2069time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.alloc: 8600880"
2070time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.heapObjects: 37869"
2071time="2020-01-11 18:53:08" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2072time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing counter go.totalAlloc: 11440"
2073time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2074time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing counter go.frees: 29"
2075time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.sys: 0"
2076time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.heapIdle: 113926144"
2077time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2078time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.heapSys: 131530752"
2079time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.heapInuse: 17604608"
2080time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2081time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2082time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.numGoroutine: 78"
2083time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2084time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.heapAlloc: 8612320"
2085time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.heapReleased: 113926144"
2086time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2087time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.alloc: 8612320"
2088time="2020-01-11 18:53:18" level=debug msg="[gostats] flushing gauge go.heapObjects: 38199"
2089time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing counter go.totalAlloc: 11600"
2090time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing counter go.mallocs: 361"
2091time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing counter go.frees: 29"
2092time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2093time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.numGoroutine: 76"
2094time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2095time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.heapAlloc: 8623920"
2096time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.heapReleased: 113926144"
2097time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2098time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.alloc: 8623920"
2099time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.heapObjects: 38531"
2100time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2101time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.sys: 0"
2102time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.heapIdle: 113958912"
2103time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.heapSys: 131563520"
2104time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge go.heapInuse: 17604608"
2105time="2020-01-11 18:53:28" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2106time="2020-01-11 18:53:28" level=info msg="Iteration started timer " subsystem=fetcher
2107time="2020-01-11 18:53:28" level=debug msg="HTTP GET" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
21082020-01-11 18:53:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_31] INFO: 1A5B8D82-D6E1-4CEE-99FF-F68C46929DB4: 127.0.0.1 "GET /ambassador/v0/diag/" START
21092020-01-11 18:53:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_31] INFO: DEBUG_MODE False
2110status_dict {'CRDs': {'status': False, 'specifics': [(False, 'Core CRD type definitions are missing')]}, 'Error check': {'status': False, 'specifics': [(False, '1 total error logged')]}, 'TLS': {'status': True, 'specifics': [(True, '1 TLSContext is active')]}, 'Mappings': {'status': True, 'specifics': [(True, '4 Mappings are active')]}}
21112020-01-11 18:53:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_31] INFO: 1A5B8D82-D6E1-4CEE-99FF-F68C46929DB4: 127.0.0.1 "GET /ambassador/v0/diag/" 14ms 200 success
2112time="2020-01-11 18:53:28" level=debug msg="GET succeeded" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
2113time="2020-01-11 18:53:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-direct-mapping name=edgestack-direct-mapping namespace=default prefix=/edge_stack rewrite=/edge_stack_ui/edge_stack/ subsystem=fetcher
2114time="2020-01-11 18:53:28" level=info msg="Found mapping" baseURL="https://ambassador.default.svc.cluster.local" name=hello namespace=default prefix=/hello subsystem=fetcher
2115time="2020-01-11 18:53:28" level=debug msg="HTTP GET" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2116time="2020-01-11 18:53:28" level=error msg="Bad HTTP response" status_code=404 subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2117time="2020-01-11 18:53:28" level=error msg="HTTP error 404 from https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2118time="2020-01-11 18:53:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=ambassador-edge-stack name=ambassador-edge-stack namespace=default prefix=/.ambassador rewrite= subsystem=fetcher
2119time="2020-01-11 18:53:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-fallback-mapping name=edgestack-fallback-mapping namespace=default prefix= rewrite=/edge_stack_ui/ subsystem=fetcher
2120time="2020-01-11 18:53:28" level=info msg="Iteration done" subsystem=fetcher
2121time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing counter go.totalAlloc: 787968"
2122time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing counter go.mallocs: 8995"
2123time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing counter go.frees: 1520"
2124time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.heapReleased: 113590272"
2125time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2126time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2127time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.numGoroutine: 76"
2128time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2129time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.heapAlloc: 9411888"
2130time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.heapObjects: 46006"
2131time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2132time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.alloc: 9411888"
2133time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.heapIdle: 113623040"
2134time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.sys: 0"
2135time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.heapInuse: 17973248"
2136time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2137time="2020-01-11 18:53:38" level=debug msg="[gostats] flushing gauge go.heapSys: 131596288"
2138ACCESS [2020-01-11T18:53:28.759Z] "GET /hello/.ambassador-internal/openapi-docs HTTP/1.1" 404 - 0 232 1 1 "10.42.0.10" "Go-http-client/1.1" "fa0f94c6-f355-4546-b76e-005a0a9a6e8b" "127.0.0.1:8443" "10.43.207.150:80"
2139time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2140time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing counter go.frees: 30"
2141time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing counter go.totalAlloc: 11424"
2142time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.alloc: 9423312"
2143time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.heapObjects: 46335"
2144time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2145time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.sys: 0"
2146time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.heapIdle: 113623040"
2147time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.heapSys: 131596288"
2148time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.heapInuse: 17973248"
2149time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2150time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2151time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.numGoroutine: 76"
2152time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2153time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.heapAlloc: 9423312"
2154time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.heapReleased: 113590272"
2155time="2020-01-11 18:53:48" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2156ACCESS [2020-01-11T18:53:43.425Z] "GET /hello/ HTTP/1.1" 200 - 0 14 1 1 "10.42.0.10" "curl/7.58.0" "b957eca5-ab30-4438-b98c-2042b1595d87" "localhost:9443" "10.43.207.150:80"
2157ACCESS [2020-01-11T18:53:48.088Z] "GET /hello/ HTTP/1.1" 200 - 0 14 1 1 "10.42.0.10" "curl/7.58.0" "1de1e45f-4be1-4e5c-9d3f-83c081d29a78" "localhost:9443" "10.43.207.150:80"
2158time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing counter go.totalAlloc: 14432"
2159time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing counter go.mallocs: 385"
2160time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing counter go.frees: 29"
2161time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.alloc: 9437744"
2162time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.heapObjects: 46691"
2163time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2164time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.sys: 0"
2165time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.heapIdle: 113819648"
2166time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.heapSys: 131792896"
2167time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.heapInuse: 17973248"
2168time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2169time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.heapAlloc: 9437744"
2170time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.heapReleased: 113590272"
2171time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2172time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2173time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge go.numGoroutine: 30"
2174time="2020-01-11 18:53:58" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2175ACCESS [2020-01-11T18:53:50.397Z] "GET /hello/ HTTP/1.1" 200 - 0 14 1 1 "10.42.0.10" "curl/7.58.0" "7196c930-80a0-4717-8ef4-f6b37d621084" "localhost:9443" "10.43.207.150:80"
2176ACCESS [2020-01-11T18:53:53.819Z] "GET /hello/ HTTP/1.1" 200 - 0 14 1 1 "10.42.0.10" "curl/7.58.0" "aba8e465-d4b7-4e4e-9d31-d0b4efa89b66" "localhost:9443" "10.43.207.150:80"
2177time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing counter go.totalAlloc: 11664"
2178time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing counter go.mallocs: 362"
2179time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing counter go.frees: 30"
2180time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.heapReleased: 113590272"
2181time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2182time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2183time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2184time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2185time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.heapAlloc: 9449408"
2186time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.heapObjects: 47023"
2187time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2188time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.alloc: 9449408"
2189time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.heapIdle: 113885184"
2190time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.sys: 0"
2191time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.heapInuse: 17973248"
2192time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2193time="2020-01-11 18:54:08" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2194time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing counter go.totalAlloc: 11440"
2195time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing counter go.frees: 29"
2196time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2197time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2198time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.alloc: 9460848"
2199time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.heapObjects: 47353"
2200time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.sys: 0"
2201time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.heapIdle: 113885184"
2202time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2203time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2204time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.heapInuse: 17973248"
2205time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2206time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2207time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2208time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2209time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.heapAlloc: 9460848"
2210time="2020-01-11 18:54:18" level=debug msg="[gostats] flushing gauge go.heapReleased: 113590272"
2211time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing counter go.totalAlloc: 11440"
2212time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2213time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing counter go.frees: 29"
2214time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.heapInuse: 17973248"
2215time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2216time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2217time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.heapReleased: 113590272"
2218time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.nextGC: 11009408"
2219time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768748782951590"
2220time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2221time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2222time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.heapAlloc: 9472288"
2223time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.heapObjects: 47683"
2224time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2225time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.alloc: 9472288"
2226time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.heapIdle: 113885184"
2227time="2020-01-11 18:54:28" level=debug msg="[gostats] flushing gauge go.sys: 0"
2228time="2020-01-11 18:54:28" level=info msg="Iteration started timer " subsystem=fetcher
2229time="2020-01-11 18:54:28" level=debug msg="HTTP GET" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
22302020-01-11 18:54:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_2] INFO: DF461F18-2FC1-4881-B48E-C8EAD5104241: 127.0.0.1 "GET /ambassador/v0/diag/" START
22312020-01-11 18:54:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_2] INFO: DEBUG_MODE False
2232status_dict {'CRDs': {'status': False, 'specifics': [(False, 'Core CRD type definitions are missing')]}, 'Error check': {'status': False, 'specifics': [(False, '1 total error logged')]}, 'TLS': {'status': True, 'specifics': [(True, '1 TLSContext is active')]}, 'Mappings': {'status': True, 'specifics': [(True, '4 Mappings are active')]}}
22332020-01-11 18:54:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_2] INFO: DF461F18-2FC1-4881-B48E-C8EAD5104241: 127.0.0.1 "GET /ambassador/v0/diag/" 13ms 200 success
2234time="2020-01-11 18:54:28" level=debug msg="GET succeeded" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
2235time="2020-01-11 18:54:28" level=info msg="Found mapping" baseURL="https://ambassador.default.svc.cluster.local" name=hello namespace=default prefix=/hello subsystem=fetcher
2236time="2020-01-11 18:54:28" level=debug msg="HTTP GET" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2237time="2020-01-11 18:54:28" level=error msg="Bad HTTP response" status_code=404 subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2238time="2020-01-11 18:54:28" level=error msg="HTTP error 404 from https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2239time="2020-01-11 18:54:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=ambassador-edge-stack name=ambassador-edge-stack namespace=default prefix=/.ambassador rewrite= subsystem=fetcher
2240time="2020-01-11 18:54:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-fallback-mapping name=edgestack-fallback-mapping namespace=default prefix= rewrite=/edge_stack_ui/ subsystem=fetcher
2241time="2020-01-11 18:54:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-direct-mapping name=edgestack-direct-mapping namespace=default prefix=/edge_stack rewrite=/edge_stack_ui/edge_stack/ subsystem=fetcher
2242time="2020-01-11 18:54:28" level=info msg="Iteration done" subsystem=fetcher
2243time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing counter go.numGC: 1"
2244time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing counter go.pauseTotalNs: 16060"
2245time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing counter go.totalAlloc: 777560"
2246time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing counter go.frees: 30780"
2247time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing counter go.mallocs: 8956"
2248time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.heapInuse: 10862592"
2249time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2250time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2251time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.heapReleased: 121028608"
2252time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2253time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2254time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2255time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2256time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4752728"
2257time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.heapObjects: 25859"
2258time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2259time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.alloc: 4752728"
2260time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.heapIdle: 121028608"
2261time="2020-01-11 18:54:38" level=debug msg="[gostats] flushing gauge go.sys: 0"
2262ACCESS [2020-01-11T18:54:28.759Z] "GET /hello/.ambassador-internal/openapi-docs HTTP/1.1" 404 - 0 232 1 1 "10.42.0.10" "Go-http-client/1.1" "7f0b6038-a36e-426b-bc85-b1aad1bff3e4" "127.0.0.1:8443" "10.43.207.150:80"
2263time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing counter go.totalAlloc: 18872"
2264time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing counter go.frees: 33"
2265time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing counter go.mallocs: 403"
2266time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.sys: 0"
2267time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.heapIdle: 121028608"
2268time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2269time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.heapInuse: 10862592"
2270time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2271time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4771600"
2272time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.heapReleased: 121028608"
2273time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2274time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2275time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2276time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2277time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.alloc: 4771600"
2278time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.heapObjects: 26229"
2279time="2020-01-11 18:54:48" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2280time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2281time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing counter go.frees: 29"
2282time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing counter go.totalAlloc: 11440"
2283time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.alloc: 4783040"
2284time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.heapObjects: 26559"
2285time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2286time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.sys: 0"
2287time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.heapIdle: 121028608"
2288time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2289time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.heapInuse: 10862592"
2290time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2291time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4783040"
2292time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.heapReleased: 121028608"
2293time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2294time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2295time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2296time="2020-01-11 18:54:58" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2297time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing counter go.totalAlloc: 11424"
2298time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2299time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing counter go.frees: 30"
2300time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2301time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2302time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2303time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2304time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4794464"
2305time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.heapReleased: 121028608"
2306time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2307time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.alloc: 4794464"
2308time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.heapObjects: 26888"
2309time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.sys: 0"
2310time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.heapIdle: 121028608"
2311time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2312time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2313time="2020-01-11 18:55:08" level=debug msg="[gostats] flushing gauge go.heapInuse: 10862592"
2314time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing counter go.totalAlloc: 11424"
2315time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2316time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing counter go.frees: 30"
2317time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2318time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.heapInuse: 10862592"
2319time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2320time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2321time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2322time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4805888"
2323time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.heapReleased: 121028608"
2324time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2325time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2326time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.alloc: 4805888"
2327time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.heapObjects: 27217"
2328time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2329time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.sys: 0"
2330time="2020-01-11 18:55:18" level=debug msg="[gostats] flushing gauge go.heapIdle: 121028608"
2331time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing counter go.totalAlloc: 11440"
2332time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2333time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing counter go.frees: 29"
2334time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.heapReleased: 121028608"
2335time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2336time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2337time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2338time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2339time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4817328"
2340time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.heapObjects: 27547"
2341time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2342time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.alloc: 4817328"
2343time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.heapIdle: 121028608"
2344time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.sys: 0"
2345time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.heapInuse: 10862592"
2346time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2347time="2020-01-11 18:55:28" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2348time="2020-01-11 18:55:28" level=info msg="Iteration started timer " subsystem=fetcher
2349time="2020-01-11 18:55:28" level=debug msg="HTTP GET" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
23502020-01-11 18:55:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_13] INFO: 94F04243-C1AC-413D-AE27-75808F241DC7: 127.0.0.1 "GET /ambassador/v0/diag/" START
23512020-01-11 18:55:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_13] INFO: DEBUG_MODE False
2352status_dict {'CRDs': {'status': False, 'specifics': [(False, 'Core CRD type definitions are missing')]}, 'Error check': {'status': False, 'specifics': [(False, '1 total error logged')]}, 'TLS': {'status': True, 'specifics': [(True, '1 TLSContext is active')]}, 'Mappings': {'status': True, 'specifics': [(True, '4 Mappings are active')]}}
23532020-01-11 18:55:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_13] INFO: 94F04243-C1AC-413D-AE27-75808F241DC7: 127.0.0.1 "GET /ambassador/v0/diag/" 15ms 200 success
2354time="2020-01-11 18:55:28" level=debug msg="GET succeeded" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
2355time="2020-01-11 18:55:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=ambassador-edge-stack name=ambassador-edge-stack namespace=default prefix=/.ambassador rewrite= subsystem=fetcher
2356time="2020-01-11 18:55:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-fallback-mapping name=edgestack-fallback-mapping namespace=default prefix= rewrite=/edge_stack_ui/ subsystem=fetcher
2357time="2020-01-11 18:55:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-direct-mapping name=edgestack-direct-mapping namespace=default prefix=/edge_stack rewrite=/edge_stack_ui/edge_stack/ subsystem=fetcher
2358time="2020-01-11 18:55:28" level=info msg="Found mapping" baseURL="https://ambassador.default.svc.cluster.local" name=hello namespace=default prefix=/hello subsystem=fetcher
2359time="2020-01-11 18:55:28" level=debug msg="HTTP GET" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2360time="2020-01-11 18:55:28" level=error msg="Bad HTTP response" status_code=404 subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2361time="2020-01-11 18:55:28" level=error msg="HTTP error 404 from https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2362time="2020-01-11 18:55:28" level=info msg="Iteration done" subsystem=fetcher
2363time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing counter go.totalAlloc: 792456"
2364time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing counter go.mallocs: 8975"
2365time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing counter go.frees: 1517"
2366time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.sys: 0"
2367time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.heapIdle: 120619008"
2368time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2369time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.heapInuse: 11239424"
2370time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2371time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2372time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5609784"
2373time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.heapReleased: 120619008"
2374time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2375time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2376time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2377time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.alloc: 5609784"
2378time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.heapObjects: 35005"
2379time="2020-01-11 18:55:38" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2380ACCESS [2020-01-11T18:55:28.764Z] "GET /hello/.ambassador-internal/openapi-docs HTTP/1.1" 404 - 0 232 1 1 "10.42.0.10" "Go-http-client/1.1" "678b0235-dabd-4606-b52a-fc53e39abe89" "127.0.0.1:8443" "10.43.207.150:80"
2381time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing counter go.totalAlloc: 11424"
2382time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2383time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing counter go.frees: 30"
2384time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2385time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.alloc: 5621208"
2386time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.heapObjects: 35334"
2387time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.sys: 0"
2388time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.heapIdle: 120619008"
2389time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2390time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2391time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.heapInuse: 11239424"
2392time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2393time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2394time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2395time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2396time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5621208"
2397time="2020-01-11 18:55:48" level=debug msg="[gostats] flushing gauge go.heapReleased: 120619008"
2398time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing counter go.totalAlloc: 11424"
2399time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2400time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing counter go.frees: 30"
2401time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2402time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.heapInuse: 11239424"
2403time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2404time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5632632"
2405time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.heapReleased: 120619008"
2406time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2407time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2408time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2409time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2410time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.alloc: 5632632"
2411time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.heapObjects: 35663"
2412time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2413time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.sys: 0"
2414time="2020-01-11 18:55:58" level=debug msg="[gostats] flushing gauge go.heapIdle: 120619008"
2415time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing counter go.totalAlloc: 11424"
2416time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2417time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing counter go.frees: 30"
2418time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2419time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2420time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.heapInuse: 11239424"
2421time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2422time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2423time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2424time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2425time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5644056"
2426time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.heapReleased: 120619008"
2427time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2428time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.alloc: 5644056"
2429time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.heapObjects: 35992"
2430time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.sys: 0"
2431time="2020-01-11 18:56:08" level=debug msg="[gostats] flushing gauge go.heapIdle: 120619008"
2432time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2433time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing counter go.frees: 30"
2434time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing counter go.totalAlloc: 11424"
2435time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5655480"
2436time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.heapReleased: 120619008"
2437time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2438time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2439time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2440time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2441time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.alloc: 5655480"
2442time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.heapObjects: 36321"
2443time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2444time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.sys: 0"
2445time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.heapIdle: 120619008"
2446time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2447time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge go.heapInuse: 11239424"
2448time="2020-01-11 18:56:18" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2449time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing counter go.totalAlloc: 11440"
2450time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2451time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing counter go.frees: 29"
2452time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.heapObjects: 36651"
2453time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2454time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.alloc: 5666920"
2455time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.heapIdle: 120619008"
2456time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.sys: 0"
2457time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.heapInuse: 11239424"
2458time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2459time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2460time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.heapReleased: 120619008"
2461time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.nextGC: 9507008"
2462time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768869622258063"
2463time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2464time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2465time="2020-01-11 18:56:28" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5666920"
2466time="2020-01-11 18:56:28" level=info msg="Iteration started timer " subsystem=fetcher
2467time="2020-01-11 18:56:28" level=debug msg="HTTP GET" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
24682020-01-11 18:56:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_15] INFO: 141F287D-44C9-4A60-9D03-BE7C6C01576F: 127.0.0.1 "GET /ambassador/v0/diag/" START
24692020-01-11 18:56:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_15] INFO: DEBUG_MODE False
2470status_dict {'CRDs': {'status': False, 'specifics': [(False, 'Core CRD type definitions are missing')]}, 'Error check': {'status': False, 'specifics': [(False, '1 total error logged')]}, 'TLS': {'status': True, 'specifics': [(True, '1 TLSContext is active')]}, 'Mappings': {'status': True, 'specifics': [(True, '4 Mappings are active')]}}
24712020-01-11 18:56:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_15] INFO: 141F287D-44C9-4A60-9D03-BE7C6C01576F: 127.0.0.1 "GET /ambassador/v0/diag/" 12ms 200 success
2472time="2020-01-11 18:56:28" level=debug msg="GET succeeded" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
2473time="2020-01-11 18:56:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-direct-mapping name=edgestack-direct-mapping namespace=default prefix=/edge_stack rewrite=/edge_stack_ui/edge_stack/ subsystem=fetcher
2474time="2020-01-11 18:56:28" level=info msg="Found mapping" baseURL="https://ambassador.default.svc.cluster.local" name=hello namespace=default prefix=/hello subsystem=fetcher
2475time="2020-01-11 18:56:28" level=debug msg="HTTP GET" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2476time="2020-01-11 18:56:28" level=error msg="Bad HTTP response" status_code=404 subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2477time="2020-01-11 18:56:28" level=error msg="HTTP error 404 from https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2478time="2020-01-11 18:56:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=ambassador-edge-stack name=ambassador-edge-stack namespace=default prefix=/.ambassador rewrite= subsystem=fetcher
2479time="2020-01-11 18:56:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-fallback-mapping name=edgestack-fallback-mapping namespace=default prefix= rewrite=/edge_stack_ui/ subsystem=fetcher
2480time="2020-01-11 18:56:28" level=info msg="Iteration done" subsystem=fetcher
2481time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing counter go.numGC: 1"
2482time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing counter go.pauseTotalNs: 19651"
2483time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing counter go.totalAlloc: 786984"
2484time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing counter go.mallocs: 8962"
2485time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing counter go.frees: 19783"
2486time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.alloc: 4723352"
2487time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.heapObjects: 25830"
2488time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2489time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.sys: 0"
2490time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.heapIdle: 121167872"
2491time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2492time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.heapInuse: 10723328"
2493time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2494time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2495time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2496time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4723352"
2497time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.heapReleased: 121167872"
2498time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2499time="2020-01-11 18:56:38" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2500ACCESS [2020-01-11T18:56:28.758Z] "GET /hello/.ambassador-internal/openapi-docs HTTP/1.1" 404 - 0 232 1 1 "10.42.0.10" "Go-http-client/1.1" "87db0d61-e98c-4a8a-8ce7-87f2d054811e" "127.0.0.1:8443" "10.43.207.150:80"
2501time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing counter go.totalAlloc: 19640"
2502time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing counter go.mallocs: 411"
2503time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing counter go.frees: 32"
2504time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2505time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.heapInuse: 10723328"
2506time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2507time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2508time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2509time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4742992"
2510time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.heapReleased: 121167872"
2511time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2512time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2513time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.alloc: 4742992"
2514time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.heapObjects: 26209"
2515time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2516time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.sys: 0"
2517time="2020-01-11 18:56:48" level=debug msg="[gostats] flushing gauge go.heapIdle: 121167872"
2518time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing counter go.totalAlloc: 12192"
2519time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing counter go.mallocs: 367"
2520time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing counter go.frees: 30"
2521time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.sys: 0"
2522time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.heapIdle: 121167872"
2523time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2524time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.heapInuse: 10723328"
2525time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2526time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4755184"
2527time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.heapReleased: 121167872"
2528time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2529time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2530time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2531time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2532time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.alloc: 4755184"
2533time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.heapObjects: 26546"
2534time="2020-01-11 18:56:58" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2535time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing counter go.totalAlloc: 12208"
2536time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing counter go.mallocs: 367"
2537time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing counter go.frees: 29"
2538time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.sys: 0"
2539time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.heapIdle: 121167872"
2540time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2541time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.heapInuse: 10723328"
2542time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2543time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2544time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2545time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4767392"
2546time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.heapReleased: 121167872"
2547time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2548time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2549time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.alloc: 4767392"
2550time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.heapObjects: 26884"
2551time="2020-01-11 18:57:08" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2552ACCESS [2020-01-11T18:57:05.631Z] "GET /hello/ HTTP/1.1" 200 - 0 14 1 1 "10.42.0.10" "curl/7.58.0" "7daf6b47-34b2-4807-8364-c891017d2561" "localhost:9443" "10.43.207.150:80"
2553time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing counter go.totalAlloc: 12192"
2554time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing counter go.mallocs: 367"
2555time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing counter go.frees: 30"
2556time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.alloc: 4779584"
2557time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.heapObjects: 27221"
2558time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2559time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.sys: 0"
2560time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.heapIdle: 121167872"
2561time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2562time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.heapInuse: 10723328"
2563time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2564time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2565time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2566time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2567time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4779584"
2568time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.heapReleased: 121167872"
2569time="2020-01-11 18:57:18" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2570time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing counter go.totalAlloc: 11440"
2571time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2572time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing counter go.frees: 29"
2573time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.heapSys: 131891200"
2574time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.heapInuse: 10723328"
2575time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2576time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2577time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2578time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2579time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.heapAlloc: 4791024"
2580time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.heapReleased: 121167872"
2581time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2582time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.alloc: 4791024"
2583time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.heapObjects: 27551"
2584time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2585time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.sys: 0"
2586time="2020-01-11 18:57:28" level=debug msg="[gostats] flushing gauge go.heapIdle: 121167872"
2587time="2020-01-11 18:57:28" level=info msg="Iteration started timer " subsystem=fetcher
2588time="2020-01-11 18:57:28" level=debug msg="HTTP GET" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
25892020-01-11 18:57:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_27] INFO: DE2DFE58-5B3A-4589-B90D-4F7296EEA1F9: 127.0.0.1 "GET /ambassador/v0/diag/" START
25902020-01-11 18:57:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_27] INFO: DEBUG_MODE False
2591status_dict {'CRDs': {'status': False, 'specifics': [(False, 'Core CRD type definitions are missing')]}, 'Error check': {'status': False, 'specifics': [(False, '1 total error logged')]}, 'TLS': {'status': True, 'specifics': [(True, '1 TLSContext is active')]}, 'Mappings': {'status': True, 'specifics': [(True, '4 Mappings are active')]}}
25922020-01-11 18:57:28 diagd 1.0.0 [P303TThreadPoolExecutor-0_27] INFO: DE2DFE58-5B3A-4589-B90D-4F7296EEA1F9: 127.0.0.1 "GET /ambassador/v0/diag/" 12ms 200 success
2593time="2020-01-11 18:57:28" level=debug msg="GET succeeded" subsystem=fetcher url="http://127.0.0.1:8877/ambassador/v0/diag/?json=true"
2594time="2020-01-11 18:57:28" level=info msg="Found mapping" baseURL="https://ambassador.default.svc.cluster.local" name=hello namespace=default prefix=/hello subsystem=fetcher
2595time="2020-01-11 18:57:28" level=debug msg="HTTP GET" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2596time="2020-01-11 18:57:28" level=error msg="Bad HTTP response" status_code=404 subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2597time="2020-01-11 18:57:28" level=error msg="HTTP error 404 from https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs" subsystem=fetcher url="https://127.0.0.1:8443/hello/.ambassador-internal/openapi-docs"
2598time="2020-01-11 18:57:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=ambassador-edge-stack name=ambassador-edge-stack namespace=default prefix=/.ambassador rewrite= subsystem=fetcher
2599time="2020-01-11 18:57:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-fallback-mapping name=edgestack-fallback-mapping namespace=default prefix= rewrite=/edge_stack_ui/ subsystem=fetcher
2600time="2020-01-11 18:57:28" level=info msg="Found internal mapping, skipping" baseURL="https://ambassador.default.svc.cluster.local" clusterName=cluster_127_0_0_1_8500_default mappingName=edgestack-direct-mapping name=edgestack-direct-mapping namespace=default prefix=/edge_stack rewrite=/edge_stack_ui/edge_stack/ subsystem=fetcher
2601time="2020-01-11 18:57:28" level=info msg="Iteration done" subsystem=fetcher
2602time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing counter go.totalAlloc: 797720"
2603time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing counter go.mallocs: 8975"
2604time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing counter go.frees: 1519"
2605time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2606time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.heapInuse: 11091968"
2607time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2608time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5588744"
2609time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.heapReleased: 120766464"
2610time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2611time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2612time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2613time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2614time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.alloc: 5588744"
2615time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.heapObjects: 35007"
2616time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2617time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.sys: 0"
2618time="2020-01-11 18:57:38" level=debug msg="[gostats] flushing gauge go.heapIdle: 120766464"
2619ACCESS [2020-01-11T18:57:28.758Z] "GET /hello/.ambassador-internal/openapi-docs HTTP/1.1" 404 - 0 232 2 1 "10.42.0.10" "Go-http-client/1.1" "10d442fc-201a-4558-870b-7ecbb130d033" "127.0.0.1:8443" "10.43.207.150:80"
2620time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing counter go.frees: 30"
2621time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2622time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing counter go.totalAlloc: 11424"
2623time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.sys: 0"
2624time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.heapIdle: 120766464"
2625time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2626time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.heapInuse: 11091968"
2627time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2628time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5600168"
2629time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.heapReleased: 120766464"
2630time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2631time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2632time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2633time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2634time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.alloc: 5600168"
2635time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.heapObjects: 35336"
2636time="2020-01-11 18:57:48" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2637time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing counter go.totalAlloc: 11424"
2638time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing counter go.frees: 30"
2639time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2640time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2641time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.alloc: 5611592"
2642time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.heapObjects: 35665"
2643time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.sys: 0"
2644time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.heapIdle: 120766464"
2645time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2646time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2647time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.heapInuse: 11091968"
2648time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2649time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2650time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2651time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2652time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5611592"
2653time="2020-01-11 18:57:58" level=debug msg="[gostats] flushing gauge go.heapReleased: 120766464"
2654time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing counter go.totalAlloc: 11424"
2655time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2656time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing counter go.frees: 30"
2657time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.alloc: 5623016"
2658time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.heapObjects: 35994"
2659time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"
2660time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.sys: 0"
2661time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.heapIdle: 120766464"
2662time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2663time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.heapInuse: 11091968"
2664time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2665time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2666time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2667time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2668time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5623016"
2669time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.heapReleased: 120766464"
2670time="2020-01-11 18:58:08" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2671time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing counter go.totalAlloc: 11440"
2672time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing counter go.mallocs: 359"
2673time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing counter go.frees: 29"
2674time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.sys: 0"
2675time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.heapIdle: 120766464"
2676time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.heapSys: 131858432"
2677time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.heapInuse: 11091968"
2678time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge ratelimit.runtime.num_values: 0"
2679time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.numGoroutine: 24"
2680time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge ratelimit.redis_pool.cx_active: 0"
2681time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.heapAlloc: 5634456"
2682time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.heapReleased: 120766464"
2683time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.nextGC: 9448512"
2684time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.lastGC: 1578768990622372784"
2685time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.alloc: 5634456"
2686time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.heapObjects: 36324"
2687time="2020-01-11 18:58:18" level=debug msg="[gostats] flushing gauge go.gcCPUPercent: 0"