receiver.envoy.als.Fetcher show error log: code:0 header:null body:null

[liyongxin]

Please answer these questions before submitting your issue.

• Why do you submit this issue?
• Question or discussion
• Bug
• Requirement
• Feature or performance improvement

---

Question

• What do you want to know?
  I installed the latest istio 1.9.1 version, opened envoyAccessLogService.address=skywalking-oap.istio-system:11800, and deployed istio's bookinfo program.
  At the same time, the following command was executed to install version 8.1.0 of skywalking:

git clone https://github.com/apache/skywalking-kubernetes.git

cd skywalking-kubernetes/chart

helm repo add elastic https://helm.elastic.co

helm dep up skywalking

helm install 8.1.0 skywalking -n istio-system \
  --set oap.env.SW_ENVOY_METRIC_ALS_HTTP_ANALYSIS=k8s-mesh \
  --set fullnameOverride=skywalking \
  --set oap.envoy.als.enabled=true \
  --set ui.image.tag=8.1.0 \
  --set oap.image.tag=8.1.0-es6 \
  --set oap.storageType=elasticsearch`

After the pods are started, the bookinfo ui through the gateway is normal, but there is no information when accessing the skywalking-ui.
I checked the oap log and found the following error:

2021-03-08 08:04:12,286 - org.elasticsearch.client.RestClient -47898 [I/O dispatcher 1] WARN  [] - request [HEAD http://elasticsearch-master:9200/_template/instance_jvm_thread_peak_count] returned 1 warnings: [299 Elasticsearch-6.8.6-3d9f765 "[types removal] The parameter include_type_name should be explicitly specified in get template requests to prepare for 7.0. In 7.0 include_type_name will default to 'false', which means responses will omit the type name in mapping definitions."]
2021-03-08 08:04:12,289 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -47901 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMMemoryDispatcher is added into DefaultScopeDefine 9.
2021-03-08 08:04:12,290 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -47902 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMGCDispatcher is added into DefaultScopeDefine 11.
2021-03-08 08:04:12,290 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -47902 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMThreadDispatcher is added into DefaultScopeDefine 33.
2021-03-08 08:04:12,290 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -47902 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMCPUDispatcher is added into DefaultScopeDefine 8.
2021-03-08 08:04:12,292 - org.apache.skywalking.oap.server.library.server.grpc.GRPCServer -47904 [main] INFO  [] - Bind handler JVMMetricReportServiceHandler into gRPC server 0.0.0.0:11800
2021-03-08 08:04:12,491 - org.apache.skywalking.oap.server.library.server.jetty.JettyServer -48103 [main] INFO  [] - start server, host: 0.0.0.0, port: 12800
2021-03-08 08:04:12,497 - org.eclipse.jetty.server.Server -48109 [main] INFO  [] - jetty-9.4.28.v20200408; built: 2020-04-08T17:49:39.557Z; git: ab228fde9e55e9164c738d7fa121f8ac5acd51c9; jvm 1.8.0_212-b04
2021-03-08 08:04:12,543 - org.eclipse.jetty.server.handler.ContextHandler -48155 [main] INFO  [] - Started o.e.j.s.ServletContextHandler@66a472b9{/,null,AVAILABLE}
2021-03-08 08:04:12,554 - org.eclipse.jetty.server.AbstractConnector -48166 [main] INFO  [] - Started ServerConnector@7b2a3ff8{HTTP/1.1, (http/1.1)}{0.0.0.0:12800}
2021-03-08 08:04:12,554 - org.eclipse.jetty.server.Server -48166 [main] INFO  [] - Started @48236ms
2021-03-08 08:04:12,556 - org.apache.skywalking.oap.server.core.storage.PersistenceTimer -48168 [main] INFO  [] - persistence timer start
2021-03-08 08:04:12,560 - org.apache.skywalking.oap.server.core.cache.CacheUpdateTimer -48172 [main] INFO  [] - Cache updateServiceInventory timer start
2021-03-08 08:04:26,735 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -62347 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:26,736 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -62348 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:26,737 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -62349 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:26,738 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -62350 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:26,739 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -62351 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:26,739 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -62351 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:26,739 - org.apache.skywalking.oap.server.receiver.envoy.als.K8sALSServiceMeshHTTPAnalysis -62351 [load-pod-0] INFO  [] - Load 8 pods in 5ms

2021-03-08 08:04:41,762 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -77374 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:41,763 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -77375 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:41,764 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -77376 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:41,765 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -77377 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:41,765 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -77377 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:41,766 - org.apache.skywalking.oap.server.receiver.envoy.als.Fetcher -77378 [load-pod-0] ERROR [] - code:0 header:null body:null
2021-03-08 08:04:41,766 - org.apache.skywalking.oap.server.receiver.envoy.als.K8sALSServiceMeshHTTPAnalysis -77378 [load-pod-0] INFO  [] - Load 8 pods in 5ms

oap prints the above error log cyclically, I am not sure where the problem is, please help analyze it

[wu-sheng]

From my understanding, you are using wrong version. 1.9.1 requires the 8.4.0. Istio did break changes.

[kezhenxu94]

Istio 1.9.1 only supports Envoy {access log service, metrics service} V3 API, while SkyWalking 8.1.0 only supports {access log service, metrics service} V2 API (because SkyWalking 8.1.0 is much more earlier than Istio 1.9.1), if you want to use Istio 1.9.1, please use SkyWalking 8.4.0

[liyongxin]

@wu-sheng @kezhenxu94 Sorry to interrupt again, i reinstall skywalking 8.4.0 using the following command：

helm install 8.4.0 skywalking -n istio-system \
  --set oap.env.SW_ENVOY_METRIC_ALS_HTTP_ANALYSIS=k8s-mesh \
  --set fullnameOverride=skywalking \
  --set oap.envoy.als.enabled=true \
  --set ui.image.tag=8.4.0 \
  --set oap.image.tag=8.4.0-es6 \
  --set oap.storageType=elasticsearch

but the oap show me error logs:

2021-03-08 10:20:44,303 - org.elasticsearch.client.RestClient -10628 [I/O dispatcher 1] WARN  [] - request [HEAD http://elasticsearch-master:9200/_template/instance_jvm_thread_peak_count] returned 1 warnings: [299 Elasticsearch-6.8.6-3d9f765 "[types removal] The parameter include_type_name should be explicitly specified in get template requests to prepare for 7.0. In 7.0 include_type_name will default to 'false', which means responses will omit the type name in mapping definitions."]
2021-03-08 10:20:44,305 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -10630 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMMemoryDispatcher is added into DefaultScopeDefine 9.
2021-03-08 10:20:44,306 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -10631 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMGCDispatcher is added into DefaultScopeDefine 11.
2021-03-08 10:20:44,306 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -10631 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMThreadDispatcher is added into DefaultScopeDefine 33.
2021-03-08 10:20:44,306 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -10631 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMCPUDispatcher is added into DefaultScopeDefine 8.
2021-03-08 10:20:44,308 - org.apache.skywalking.oap.server.library.server.grpc.GRPCServer -10633 [main] INFO  [] - Bind handler JVMMetricReportServiceHandler into gRPC server 0.0.0.0:11800
2021-03-08 10:20:44,310 - org.apache.skywalking.oap.server.library.server.grpc.GRPCServer -10635 [main] INFO  [] - Bind handler JVMMetricReportServiceHandlerCompat into gRPC server 0.0.0.0:11800
2021-03-08 10:20:44,312 - org.apache.skywalking.oap.server.library.module.BootstrapFlow -10637 [main] INFO  [] - start the provider default in receiver-meter module.
2021-03-08 10:20:44,312 - org.apache.skywalking.oap.server.library.server.grpc.GRPCServer -10637 [main] INFO  [] - Bind handler MeterServiceHandler into gRPC server 0.0.0.0:11800
2021-03-08 10:20:44,315 - org.apache.skywalking.oap.server.library.server.grpc.GRPCServer -10640 [main] INFO  [] - Bind handler MeterServiceHandlerCompat into gRPC server 0.0.0.0:11800
2021-03-08 10:20:44,465 - org.apache.skywalking.oap.server.library.server.jetty.JettyServer -10790 [main] INFO  [] - start server, host: 0.0.0.0, port: 12800
2021-03-08 10:20:44,470 - org.eclipse.jetty.server.Server -10795 [main] INFO  [] - jetty-9.4.28.v20200408; built: 2020-04-08T17:49:39.557Z; git: ab228fde9e55e9164c738d7fa121f8ac5acd51c9; jvm 11.0.9+11
2021-03-08 10:20:44,511 - org.eclipse.jetty.server.handler.ContextHandler -10836 [main] INFO  [] - Started o.e.j.s.ServletContextHandler@1455d0f5{/,null,AVAILABLE}
2021-03-08 10:20:44,521 - org.eclipse.jetty.server.AbstractConnector -10846 [main] INFO  [] - Started ServerConnector@1a0d96a5{HTTP/1.1, (http/1.1)}{0.0.0.0:12800}
2021-03-08 10:20:44,522 - org.eclipse.jetty.server.Server -10847 [main] INFO  [] - Started @10895ms
2021-03-08 10:20:44,523 - org.apache.skywalking.oap.server.core.storage.PersistenceTimer -10848 [main] INFO  [] - persistence timer start
2021-03-08 10:20:44,526 - org.apache.skywalking.oap.server.core.cache.CacheUpdateTimer -10851 [main] INFO  [] - Cache updateServiceInventory timer start
2021-03-08 10:20:44,887 - io.kubernetes.client.informer.cache.ProcessorListener -11212 [pool-12-thread-1] ERROR [] - failed invoking ADD event handler: null
2021-03-08 10:20:44,887 - io.kubernetes.client.informer.cache.ProcessorListener -11212 [pool-12-thread-1] ERROR [] - failed invoking ADD event handler: null
2021-03-08 10:20:44,887 - io.kubernetes.client.informer.cache.ProcessorListener -11212 [pool-12-thread-1] ERROR [] - failed invoking ADD event handler: null
2021-03-08 10:20:45,018 - io.kubernetes.client.informer.cache.ProcessorListener -11343 [pool-15-thread-1] ERROR [] - failed invoking ADD event handler: null
2021-03-08 10:20:45,521 - io.kubernetes.client.informer.cache.ProcessorListener -11846 [pool-12-thread-1] ERROR [] - failed invoking UPDATE event handler: null
2021-03-08 10:20:47,801 - io.kubernetes.client.informer.cache.ProcessorListener -14126 [pool-12-thread-1] ERROR [] - failed invoking UPDATE event handler: null

[kezhenxu94]

@liyongxin the error logs should not effect the metrics at all, but by any chance it really effects, try to build the master (with #6327) so that the real errors are printed in the logs, it was a pain that Kubernetes Java API swallows the stack trace in version < 10.0.0, see #6327

[yckbilly1929]

@wu-sheng @kezhenxu94 Sorry to interrupt again, i reinstall skywalking 8.4.0 using the following command：

helm install 8.4.0 skywalking -n istio-system \
  --set oap.env.SW_ENVOY_METRIC_ALS_HTTP_ANALYSIS=k8s-mesh \
  --set fullnameOverride=skywalking \
  --set oap.envoy.als.enabled=true \
  --set ui.image.tag=8.4.0 \
  --set oap.image.tag=8.4.0-es6 \
  --set oap.storageType=elasticsearch

but the oap show me error logs:

2021-03-08 10:20:44,303 - org.elasticsearch.client.RestClient -10628 [I/O dispatcher 1] WARN  [] - request [HEAD http://elasticsearch-master:9200/_template/instance_jvm_thread_peak_count] returned 1 warnings: [299 Elasticsearch-6.8.6-3d9f765 "[types removal] The parameter include_type_name should be explicitly specified in get template requests to prepare for 7.0. In 7.0 include_type_name will default to 'false', which means responses will omit the type name in mapping definitions."]
2021-03-08 10:20:44,305 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -10630 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMMemoryDispatcher is added into DefaultScopeDefine 9.
2021-03-08 10:20:44,306 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -10631 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMGCDispatcher is added into DefaultScopeDefine 11.
2021-03-08 10:20:44,306 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -10631 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMThreadDispatcher is added into DefaultScopeDefine 33.
2021-03-08 10:20:44,306 - org.apache.skywalking.oap.server.core.analysis.DispatcherManager -10631 [main] INFO  [] - Dispatcher org.apache.skywalking.oap.server.core.source.oal.rt.dispatcher.ServiceInstanceJVMCPUDispatcher is added into DefaultScopeDefine 8.
2021-03-08 10:20:44,308 - org.apache.skywalking.oap.server.library.server.grpc.GRPCServer -10633 [main] INFO  [] - Bind handler JVMMetricReportServiceHandler into gRPC server 0.0.0.0:11800
2021-03-08 10:20:44,310 - org.apache.skywalking.oap.server.library.server.grpc.GRPCServer -10635 [main] INFO  [] - Bind handler JVMMetricReportServiceHandlerCompat into gRPC server 0.0.0.0:11800
2021-03-08 10:20:44,312 - org.apache.skywalking.oap.server.library.module.BootstrapFlow -10637 [main] INFO  [] - start the provider default in receiver-meter module.
2021-03-08 10:20:44,312 - org.apache.skywalking.oap.server.library.server.grpc.GRPCServer -10637 [main] INFO  [] - Bind handler MeterServiceHandler into gRPC server 0.0.0.0:11800
2021-03-08 10:20:44,315 - org.apache.skywalking.oap.server.library.server.grpc.GRPCServer -10640 [main] INFO  [] - Bind handler MeterServiceHandlerCompat into gRPC server 0.0.0.0:11800
2021-03-08 10:20:44,465 - org.apache.skywalking.oap.server.library.server.jetty.JettyServer -10790 [main] INFO  [] - start server, host: 0.0.0.0, port: 12800
2021-03-08 10:20:44,470 - org.eclipse.jetty.server.Server -10795 [main] INFO  [] - jetty-9.4.28.v20200408; built: 2020-04-08T17:49:39.557Z; git: ab228fde9e55e9164c738d7fa121f8ac5acd51c9; jvm 11.0.9+11
2021-03-08 10:20:44,511 - org.eclipse.jetty.server.handler.ContextHandler -10836 [main] INFO  [] - Started o.e.j.s.ServletContextHandler@1455d0f5{/,null,AVAILABLE}
2021-03-08 10:20:44,521 - org.eclipse.jetty.server.AbstractConnector -10846 [main] INFO  [] - Started ServerConnector@1a0d96a5{HTTP/1.1, (http/1.1)}{0.0.0.0:12800}
2021-03-08 10:20:44,522 - org.eclipse.jetty.server.Server -10847 [main] INFO  [] - Started @10895ms
2021-03-08 10:20:44,523 - org.apache.skywalking.oap.server.core.storage.PersistenceTimer -10848 [main] INFO  [] - persistence timer start
2021-03-08 10:20:44,526 - org.apache.skywalking.oap.server.core.cache.CacheUpdateTimer -10851 [main] INFO  [] - Cache updateServiceInventory timer start
2021-03-08 10:20:44,887 - io.kubernetes.client.informer.cache.ProcessorListener -11212 [pool-12-thread-1] ERROR [] - failed invoking ADD event handler: null
2021-03-08 10:20:44,887 - io.kubernetes.client.informer.cache.ProcessorListener -11212 [pool-12-thread-1] ERROR [] - failed invoking ADD event handler: null
2021-03-08 10:20:44,887 - io.kubernetes.client.informer.cache.ProcessorListener -11212 [pool-12-thread-1] ERROR [] - failed invoking ADD event handler: null
2021-03-08 10:20:45,018 - io.kubernetes.client.informer.cache.ProcessorListener -11343 [pool-15-thread-1] ERROR [] - failed invoking ADD event handler: null
2021-03-08 10:20:45,521 - io.kubernetes.client.informer.cache.ProcessorListener -11846 [pool-12-thread-1] ERROR [] - failed invoking UPDATE event handler: null
2021-03-08 10:20:47,801 - io.kubernetes.client.informer.cache.ProcessorListener -14126 [pool-12-thread-1] ERROR [] - failed invoking UPDATE event handler: null

i'm now testing on istio 1.9.2, elastic-search 7.12.0 and oap 8.5.0
metrics working but there are no traces, wonder if this is related issues
below are the stacktrace:

2021-04-15 03:09:43,893 - io.kubernetes.client.informer.cache.ProcessorListener -199718 [pool-15-thread-1] ERROR [] - failed invoking ADD event handler: {}
java.lang.NullPointerException: null
	at java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1011) ~[?:?]
	at java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006) ~[?:?]
	at org.apache.skywalking.oap.server.receiver.envoy.als.k8s.K8SServiceRegistry.lambda$addPod$5(K8SServiceRegistry.java:218) ~[envoy-metrics-receiver-plugin-8.5.0.jar:8.5.0]
	at java.util.Optional.ifPresent(Optional.java:183) ~[?:?]
	at org.apache.skywalking.oap.server.receiver.envoy.als.k8s.K8SServiceRegistry.addPod(K8SServiceRegistry.java:217) ~[envoy-metrics-receiver-plugin-8.5.0.jar:8.5.0]
	at org.apache.skywalking.oap.server.receiver.envoy.als.k8s.K8SServiceRegistry$3.onAdd(K8SServiceRegistry.java:187) ~[envoy-metrics-receiver-plugin-8.5.0.jar:8.5.0]
	at org.apache.skywalking.oap.server.receiver.envoy.als.k8s.K8SServiceRegistry$3.onAdd(K8SServiceRegistry.java:184) ~[envoy-metrics-receiver-plugin-8.5.0.jar:8.5.0]
	at io.kubernetes.client.informer.cache.ProcessorListener.run(ProcessorListener.java:71) [client-java-10.0.0.jar:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]
2021-04-15 03:09:43,932 - io.kubernetes.client.informer.cache.ProcessorListener -199757 [pool-15-thread-1] ERROR [] - failed invoking UPDATE event handler: {}
java.lang.NullPointerException: null
	at java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1011) ~[?:?]
	at java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006) ~[?:?]
	at org.apache.skywalking.oap.server.receiver.envoy.als.k8s.K8SServiceRegistry.lambda$addPod$5(K8SServiceRegistry.java:218) ~[envoy-metrics-receiver-plugin-8.5.0.jar:8.5.0]
	at java.util.Optional.ifPresent(Optional.java:183) ~[?:?]
	at org.apache.skywalking.oap.server.receiver.envoy.als.k8s.K8SServiceRegistry.addPod(K8SServiceRegistry.java:217) ~[envoy-metrics-receiver-plugin-8.5.0.jar:8.5.0]
	at org.apache.skywalking.oap.server.receiver.envoy.als.k8s.K8SServiceRegistry$3.onUpdate(K8SServiceRegistry.java:192) ~[envoy-metrics-receiver-plugin-8.5.0.jar:8.5.0]
	at org.apache.skywalking.oap.server.receiver.envoy.als.k8s.K8SServiceRegistry$3.onUpdate(K8SServiceRegistry.java:184) ~[envoy-metrics-receiver-plugin-8.5.0.jar:8.5.0]
	at io.kubernetes.client.informer.cache.ProcessorListener.run(ProcessorListener.java:61) [client-java-10.0.0.jar:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]

[kezhenxu94]

i'm now testing on istio 1.9.2, elastic-search 7.12.0 and oap 8.5.0
metrics working but there are no traces, wonder if this is related issues

The exception is fixed in latest master branch.

There is no tracing ability in this case (SW + Envoy ALS), if you want, wait for istio/istio#32588