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

Created on 8 Mar 2021  ·  5Comments  ·  Source: apache/skywalking

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

question
Source
picture liyongxin

All 5 comments

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

wu-sheng picture wu-sheng on 8 Mar 2021

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

kezhenxu94 picture kezhenxu94 on 8 Mar 2021

@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
liyongxin picture liyongxin on 8 Mar 2021
👀2

@liyongxin the error logs should not effect the metrics at all, but by any chance it really effects, try to build the master (with https://github.com/apache/skywalking/pull/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 https://github.com/apache/skywalking/pull/6327

kezhenxu94 picture kezhenxu94 on 8 Mar 2021

@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) [?:?]
yckbilly1929 picture yckbilly1929 on 15 Apr 2021
Was this page helpful?
0 / 5 - 0 ratings

Related issues

yang-xiaodong picture yang-xiaodong  ·  4Comments
landonzeng picture landonzeng  ·  6Comments
wu-sheng picture wu-sheng  ·  3Comments
xiaour picture xiaour  ·  6Comments
dingsongjie picture dingsongjie  ·  4Comments