Spark dependency job not completed

[vladohotnikov]

Hi, my spark dependency job is always in 0\1 completion state.

Error from log:

{"level":"info","ts":1658428580.491553,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc00072f590, {TRANSIENT_FAILURE connection error: desc = \"transport: Error while dialing dial tcp :16685: connect: connection refused\"}","system":"grpc","grpc_log":true}

I have no idea how spark-job is linked with 16685 port. Since it should work only with Cassandra.
I'm using docker for windows k8s cluster and instal it via helm chart

Configuration:

# Enable CassandraDB generation on start
provisionDataStore:
  cassandra: true
  elasticsearch: false
cassandra:
  persistence:
    enabled: true
  config:
    cluster_size: 1
# Client agent
agent:
  image: artifactory.com/hub.docker.com/jaegertracing/jaeger-agent
  enabled: false
# UI
query:
  image: artifactory.com/hub.docker.com/jaegertracing/jaeger-query
  extraEnv:
    - name: QUERY_BASE_PATH
      value: /jaeger
  agentSidecar:
    enabled: false
# Jobs
spark:
  image: artifactory.com/hub.docker.com/jaegertracing/jaeger-query
  schedule: "45 * * * *"
  extraEnv:
    - name: LOG-LEVEL
      value: debug
  enabled: true

Full log below

2022/07/21 18:36:20 maxprocs: Leaving GOMAXPROCS=8: CPU quota undefined
{"level":"info","ts":1658428580.3954053,"caller":"flags/service.go:119","msg":"Mounting metrics handler on admin server","route":"/metrics"}
{"level":"info","ts":1658428580.395502,"caller":"flags/service.go:125","msg":"Mounting expvar handler on admin server","route":"/debug/vars"}
{"level":"info","ts":1658428580.3959494,"caller":"flags/admin.go:128","msg":"Mounting health check on admin server","route":"/"}
{"level":"info","ts":1658428580.396063,"caller":"flags/admin.go:141","msg":"Starting admin HTTP server","http-addr":":16687"}
{"level":"info","ts":1658428580.3961291,"caller":"flags/admin.go:120","msg":"Admin server started","http.host-port":"[::]:16687","health-status":"unavailable"}
{"level":"info","ts":1658428580.4685385,"caller":"cassandra/factory.go:116","msg":"Cassandra archive storage configuration is empty, skipping"}
{"level":"info","ts":1658428580.4879076,"caller":"querysvc/query_service.go:135","msg":"Archive storage not created","reason":"archive storage not configured"}
{"level":"info","ts":1658428580.4881406,"caller":"app/flags.go:132","msg":"Archive storage not initialized"}
{"level":"info","ts":1658428580.4882777,"caller":"channelz/funcs.go:340","msg":"[core][Server #1] Server created","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4884403,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] Channel created","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4884665,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] original dial target is: \":16685\"","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.48853,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] dial target \":16685\" parse failed: parse \":16685\": missing protocol scheme","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4885862,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] fallback to scheme \"passthrough\"","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4886477,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] parsed dial target is: {Scheme:passthrough Authority: Endpoint::16685 URL:{Scheme:passthrough Opaque: User: Host: Path:/:16685 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.488671,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] Channel authority set to \"localhost:16685\"","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.488907,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] Resolver state updated: {\n  \"Addresses\": [\n    {\n      \"Addr\": \":16685\",\n      \"ServerName\": \"\",\n      \"Attributes\": null,\n      \"BalancerAttributes\": null,\n      \"Type\": 0,\n      \"Metadata\": null\n    }\n  ],\n  \"ServiceConfig\": null,\n  \"Attributes\": null\n} (resolver returned new addresses)","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4890022,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] Channel switches to new LB policy \"pick_first\"","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4893384,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2 SubChannel #3] Subchannel created","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4896536,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2 SubChannel #3] Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4897642,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2 SubChannel #3] Subchannel picks a new address \":16685\" to connect","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4903677,"caller":"app/static_handler.go:181","msg":"UI config path not provided, config file will not be watched"}
{"level":"info","ts":1658428580.490545,"caller":"app/server.go:209","msg":"Query server started","http_addr":"[::]:16686","grpc_addr":"[::]:16685"}
{"level":"info","ts":1658428580.4905844,"caller":"healthcheck/handler.go:129","msg":"Health Check state change","status":"ready"}
{"level":"info","ts":1658428580.4906502,"caller":"app/server.go:292","msg":"Starting GRPC server","port":16685,"addr":":16685"}
{"level":"info","ts":1658428580.4907124,"caller":"channelz/funcs.go:340","msg":"[core][Server #1 ListenSocket #4] ListenSocket created","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4908583,"caller":"app/server.go:273","msg":"Starting HTTP server","port":16686,"addr":":16686"}
{"level":"info","ts":1658428580.4910896,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc00072f590, {CONNECTING <nil>}","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4911494,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] Channel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
{"level":"warn","ts":1658428580.49124,"caller":"channelz/funcs.go:342","msg":"[core][Channel #2 SubChannel #3] grpc: addrConn.createTransport failed to connect to {\n  \"Addr\": \":16685\",\n  \"ServerName\": \"localhost:16685\",\n  \"Attributes\": null,\n  \"BalancerAttributes\": null,\n  \"Type\": 0,\n  \"Metadata\": null\n}. Err: connection error: desc = \"transport: Error while dialing dial tcp :16685: connect: connection refused\"","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4914608,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2 SubChannel #3] Subchannel Connectivity change to TRANSIENT_FAILURE","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.491553,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc00072f590, {TRANSIENT_FAILURE connection error: desc = \"transport: Error while dialing dial tcp :16685: connect: connection refused\"}","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428580.4916155,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] Channel Connectivity change to TRANSIENT_FAILURE","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428581.4918046,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2 SubChannel #3] Subchannel Connectivity change to IDLE","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428581.4919791,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc00072f590, {IDLE connection error: desc = \"transport: Error while dialing dial tcp :16685: connect: connection refused\"}","system":"grpc","grpc_log":true}
{"level":"info","ts":1658428581.492046,"caller":"channelz/funcs.go:340","msg":"[core][Channel #2] Channel Connectivity change to IDLE","system":"grpc","grpc_log":true}

P.S. Log level enviroment don't work here =(

[albertteoh]

The original post had the image config for the spark job which pointed to:

artifactory.devops.telekom.de/hub.docker.com/jaegertracing/jaeger-query

Perhaps you meant to point this to jaegertracing/spark-dependencies?

The logs also suggest it's a Go program (I thought spark jobs were Java programs):

2022/07/21 18:36:20 maxprocs: Leaving GOMAXPROCS=8: CPU quota undefined

... and those logs look like they indeed come from jaeger-query because it listens on port 16685 for GRPC requests.

P.S. Log level environment don't work here =(

I think you will need to use LOG_LEVEL instead of LOG-LEVEL.

[vladohotnikov]

Thank you, wrong image was the problem!