search

vespa-engine / vespa

AI + Data, online. https://vespa.ai
https://vespa.ai
Apache License 2.0
5.84k stars 604 forks source link

Multinode - issues #17602

Closed abhimech001 closed 3 years ago

abhimech001 commented 3 years ago

Hi Team,

I tried to scale 3 config server, 3 container and 3 content server. Created config map with env var VESPA_CONFIGSERVERS= <3 headless host of configserver>, then created headless service. 1) Started with spinning up config server with replicas=3 pods in parallel - Took more than 10 mins to start and at every 3 mins the config senitel service stopped and start. Is it usual to take so much time? What all components in vespa and zookeeper log we have to monitor to say application is up and in what sequence (configserver > config senitel > logd ?? ) 2) Started with spinning up container/stateless server all 3 pods in parallel - Did not start until APPLICATION was loaded in config server and config senitel kept timing out with error of no response from config server. Does its start dependant on application being loaded? 3) Can all 3 started serially without loading application to config server.

jobergum commented 3 years ago

Hello!

https://docs.vespa.ai/en/vespa-quick-start-multinode-aws.html tries to give an overall description of a vespa multi node deployment

https://github.com/vespa-engine/vespa/issues/3588 also has some context.

abhimech001 commented 3 years ago

Hello!

https://docs.vespa.ai/en/vespa-quick-start-multinode-aws.html tries to give an overall description of a vespa multi node deployment

  • install the software on a set of named nodes
  • configure the nodes to point to a set of configuration server(s)
  • start configuration servers - and deploy the application
  • start the services which subscribes to configuration which tells them what to services should be started.

3588 also has some context.

Thank you!! Interestingly, while referring to https://docs.vespa.ai/en/vespa-quick-start-multinode-aws.html I found service.xml had slobroks added which I did not had earlier in my application

  <slobrok hostalias="admin0" />
  <slobrok hostalias="stateless0" />
  <slobrok hostalias="stateless1" />
  <slobrok hostalias="content0" />
  <slobrok hostalias="content1" />

I added the above configuration in application service xml deployed and activated it, which in turn changed the port for search from 19107 to 19108 and distributor from 19111 to 19112 which screwed readiness probe on content node and did not allowed the container to start. IS there a better way to put readiness probe in content node so that it remains stable and do not change based on application xml. (configserver is contant with probe port 19071, stateless with 8080, content with ??)

johans1 commented 3 years ago

@arnej27959 can you assist with some best practice

arnej27959 commented 3 years ago

first, in your situation you should run a setup with 1 configserver only. There's no point in multiple configservers unless A) you make sure they run on different physical machines and B) you have a production setup where it's critical that you can reconfigure your application. Note that you can take the configserver down (for upgrades, for example) without impacting production traffic, so having multiple configservers is for high availability on the next level.

when starting from scratch you should start with the configserver and make sure that is up and running. On my laptop (running in a docker container) starting the configserver itself takes ~15 seconds; if it takes 10 minutes something is definitely wrong. Checking vespa.log inside the configserver container it looks like:

[2021-04-29 04:42:41.949] INFO    : configserver     Container.com.yahoo.container.jdisc.ConfiguredApplication  Starting container
...
[2021-04-29 04:42:54.144] INFO    : configserver     Container.org.eclipse.jetty.server.Server  Started @14957ms
[2021-04-29 04:42:54.147] INFO    : configserver     Container.com.yahoo.container.jdisc.ConfiguredApplication  Switching to the latest deployed set of configurations and components. Application config generation: 0

at this point you should be able to deploy your application. Until an application has been activated, there's no config for which services the sentinel should run, so it will be unhappy, and eventually give up and be restarted. This is as expected.

thirdly, I think the point of listing the service location brokers explicitly in the example is precisely to avoid the port allocation changes you've seen. If you make changes like this it's probably easiest to restart vespa services on all your nodes.

the ports for content services are dynamically allocated, because you can have any number of services that need ports (indeed you can have 0, 1, 2, or more content clusters running on the same nodes). In my single-node setup I added an extra content cluster and got messages like this from vespa-deploy prepare:

WARNING: Change(s) between active and new application that require restart:
In cluster 'search' of type 'content':
    Restart services of type 'distributor' because:
        1) stor-communicationmanager.mbusport has changed from 19112 to 19126
stor-communicationmanager.rpcport has changed from 19113 to 19127
stor-status.httpport has changed from 19114 to 19128
In cluster 'search' of type 'content':
    Restart services of type 'storagenode' because:
        1) stor-communicationmanager.mbusport has changed from 19103 to 19117
stor-communicationmanager.rpcport has changed from 19104 to 19118
stor-status.httpport has changed from 19105 to 19119
In cluster 'search' of type 'search':
    Restart services of type 'searchnode' because:
        1) # Port to use for the rpcserver.
proton.rpcport has changed from 19106 to 19120
# Port to use for the web server
proton.httpport has changed from 19110 to 19124
# Connect spec for transactionlog server.
proton.tlsspec has changed from "tcp/c7-2.build.vespa.dev:19111" to "tcp/c7-2.build.vespa.dev:19125"
# Port number to use for listening.
translogserver.listenport has changed from 19111 to 19125
arnej27959 commented 3 years ago

it would probably be better if the quick-start-multinode-aws document didn't direct you to put the slobrok service on content nodes, I'll suggest that as a documentation improvement. Leaving them out from services.xml entirely will also work, but then they will be put on some random nodes, which at some later time may cause the kind of port allocation shuffles you've seen.

abhimech001 commented 3 years ago

first, in your situation you should run a setup with 1 configserver only. There's no point in multiple configservers unless A) you make sure they run on different physical machines and B) you have a production setup where it's critical that you can reconfigure your application. Note that you can take the configserver down (for upgrades, for example) without impacting production traffic, so having multiple configservers is for high availability on the next level.

when starting from scratch you should start with the configserver and make sure that is up and running. On my laptop (running in a docker container) starting the configserver itself takes ~15 seconds; if it takes 10 minutes something is definitely wrong. Checking vespa.log inside the configserver container it looks like:

[2021-04-29 04:42:41.949] INFO    : configserver     Container.com.yahoo.container.jdisc.ConfiguredApplication    Starting container
...
[2021-04-29 04:42:54.144] INFO    : configserver     Container.org.eclipse.jetty.server.Server    Started @14957ms
[2021-04-29 04:42:54.147] INFO    : configserver     Container.com.yahoo.container.jdisc.ConfiguredApplication    Switching to the latest deployed set of configurations and components. Application config generation: 0

at this point you should be able to deploy your application. Until an application has been activated, there's no config for which services the sentinel should run, so it will be unhappy, and eventually give up and be restarted. This is as expected.

thirdly, I think the point of listing the service location brokers explicitly in the example is precisely to avoid the port allocation changes you've seen. If you make changes like this it's probably easiest to restart vespa services on all your nodes.

the ports for content services are dynamically allocated, because you can have any number of services that need ports (indeed you can have 0, 1, 2, or more content clusters running on the same nodes). In my single-node setup I added an extra content cluster and got messages like this from vespa-deploy prepare:

WARNING: Change(s) between active and new application that require restart:
In cluster 'search' of type 'content':
    Restart services of type 'distributor' because:
        1) stor-communicationmanager.mbusport has changed from 19112 to 19126
stor-communicationmanager.rpcport has changed from 19113 to 19127
stor-status.httpport has changed from 19114 to 19128
In cluster 'search' of type 'content':
    Restart services of type 'storagenode' because:
        1) stor-communicationmanager.mbusport has changed from 19103 to 19117
stor-communicationmanager.rpcport has changed from 19104 to 19118
stor-status.httpport has changed from 19105 to 19119
In cluster 'search' of type 'search':
    Restart services of type 'searchnode' because:
        1) # Port to use for the rpcserver.
proton.rpcport has changed from 19106 to 19120
# Port to use for the web server
proton.httpport has changed from 19110 to 19124
# Connect spec for transactionlog server.
proton.tlsspec has changed from "tcp/c7-2.build.vespa.dev:19111" to "tcp/c7-2.build.vespa.dev:19125"
# Port number to use for listening.
translogserver.listenport has changed from 19111 to 19125

Thank you!!! I am using latest vespa image for my used case and even if I start config server with replica=1 it took good amount of time for me.(more than 10 mins)

Observations from vespa log 1) Started two process config server and config proxy 2) ConfigProxy component kept trying to connect to configserver host at port 19070 (RpcConfigSourceClient) 3) Then for next 4 mins service jdisc/configserver installed many components and config server starting container was received and took another 11+ mins to start configserver.

[08:39] Configserver and Config proxy process started jdisc/configserver components installed/resolved/started [08:43] configserver Container.com.yahoo.container.jdisc.ConfiguredApplication Starting container jdisc/configserver components installed/resolved/started [08:50] configserver Rpc server will listen on port 19070 [08:50] configserver Container.org.eclipse.jetty.server.Server Started @683681

Also, if content server has ports dynamically allocated, does it mean we cannot put readiness probe on content server at pod start up as we do with config server @19071 and container server @8080?

arnej27959 commented 3 years ago

to take your last question first: You can't do readiness probe on a fixed port on the content servers. Note that the container server @8080 will monitor the content nodes for the purposes of sending search requests, and there's also a cluster controller which monitors the storage layer on the content node for data feeding and recovering redundancy if necessary. To manually check health you could also run (inside the content node) something like this:

$ vespa-model-inspect host `hostname` 
...
storagenode @ c7-2.build.vespa.dev : content
search/storage/0
    tcp/c7-2.build.vespa.dev:19103 (MESSAGING)
    tcp/c7-2.build.vespa.dev:19104 (STATUS RPC)
    tcp/c7-2.build.vespa.dev:19105 (STATE STATUS HTTP)
searchnode @ c7-2.build.vespa.dev : search
search/search/cluster.search/0
    tcp/c7-2.build.vespa.dev:19106 (STATUS ADMIN RTC RPC)
    tcp/c7-2.build.vespa.dev:19107 (UNUSED)
    tcp/c7-2.build.vespa.dev:19108 (UNUSED)
    tcp/c7-2.build.vespa.dev:19109 (UNUSED)
    tcp/c7-2.build.vespa.dev:19110 (STATE HEALTH JSON HTTP)

$ curl http://c7-2.build.vespa.dev:19105/state/v1/health ; echo
{"status":{"code":"up"}}
$ curl http://c7-2.build.vespa.dev:19110/state/v1/health ; echo
{"status":{"code":"up"}}

regarding your configserver:

sounds like the configserver has way too little resources available. Is this running in AWS or do you have some other kind of setup? What kind of resources (memory/cpu) do you allocate for configserver? my first guess is that there's not enough memory allocated.

this is a typical log sample for me when I just start the configserver. Note the -Xmx2048m option to java which means it will use 2GB of java heap memory.

[arnej@c7-1 vespa]$ vespa-logfmt -l all | head
[2021-04-29 12:13:46.105] EVENT   : configserver     runserver  starting/1 name="java -Xms128m -Xmx2048m -XX:+PreserveFramePointer -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/arnej/vespa/var/crash -XX:ErrorFile=/home/arnej/vespa/var/crash/hs_err_pid%p.log -XX:+ExitOnOutOfMemoryError -XX:-OmitStackTraceInFastThrow --illegal-access=warn --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.net=ALL-UNNAMED --add-opens=java.base/jdk.internal.loader=ALL-UNNAMED -Djava.io.tmpdir=/home/arnej/vespa/tmp -Djava.library.path=/home/arnej/vespa/lib64 -Djava.awt.headless=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.net.client.defaultConnectTimeout=5000 -Dsun.net.client.defaultReadTimeout=60000 -Djavax.net.ssl.keyStoreType=JKS -Djdk.tls.rejectClientInitiatedRenegotiation=true -Djdisc.config.file=/home/arnej/vespa/var/jdisc_container/configserver.properties -Djdisc.export.packages= -Djdisc.cache.path=/home/arnej/vespa/var/vespa/bundlecache/configserver -Djdisc.debug.resources=false -Djdisc.bundle.path=/home/arnej/vespa/lib/jars -Djdisc.logger.enabled=true -Djdisc.logger.level=ALL -Djdisc.logger.tag=jdisc/configserver -Dfile.encoding=UTF-8 -Dzookeeper_log_file_prefix=/home/arnej/vespa/logs/vespa/zookeeper.configserver -cp /home/arnej/vespa/lib/jars/jdisc_core-jar-with-dependencies.jar com.yahoo.jdisc.core.StandaloneMain standalone-container-jar-with-dependencies.jar (pid 55191)"
[2021-04-29 12:13:46.710] DEBUG   : configserver     stdout Initializing application without privileges.
[2021-04-29 12:13:46.880] INFO    : jdisc/configserver org.apache.felix.framework   ServiceEvent REGISTERED
[2021-04-29 12:13:46.882] DEBUG   : jdisc/configserver /com.yahoo.jdisc.core.ApplicationLoader  App location is not a class name. Installing bundle
[2021-04-29 12:13:46.919] DEBUG   : jdisc/configserver /com.yahoo.jdisc.core.FelixFramework Installing OSGi bundle from 'file:/home/arnej/vespa/lib/jars/standalone-container-jar-with-dependencies.jar'.
[2021-04-29 12:13:46.933] INFO    : jdisc/configserver standalone-container BundleEvent INSTALLED
[2021-04-29 12:13:46.947] DEBUG   : jdisc/configserver /com.yahoo.jdisc.core.FelixFramework OSGi bundle 'standalone-container' requires install from 'configdefinitions-jar-with-dependencies.jar'.
[2021-04-29 12:13:46.947] DEBUG   : jdisc/configserver /com.yahoo.jdisc.core.FelixFramework Installing OSGi bundle from 'file:/home/arnej/vespa/lib/jars/configdefinitions-jar-with-dependencies.jar'.
[2021-04-29 12:13:46.951] INFO    : jdisc/configserver configdefinitions    BundleEvent INSTALLED
[2021-04-29 12:13:46.951] DEBUG   : jdisc/configserver /com.yahoo.jdisc.core.FelixFramework OSGi bundle 'standalone-container' requires install from 'config-provisioning-jar-with-dependencies.jar'.
[arnej@c7-1 vespa]$ vespa-logfmt -l all | grep Starting.container
[2021-04-29 12:13:49.034] INFO    : configserver     Container.com.yahoo.container.jdisc.ConfiguredApplication  Starting container
[arnej@c7-1 vespa]$ vespa-logfmt -l all | tail
[2021-04-29 12:14:01.619] INFO    : configserver     Container.com.yahoo.vespa.config.server.SuperModelManager  Super model is complete
[2021-04-29 12:14:01.621] INFO    : configserver     Container.com.yahoo.vespa.service.duper.DuperModelManager  All bootstrap tenant applications have been activated
[2021-04-29 12:14:01.836] INFO    : configserver     Container.com.yahoo.vespa.config.server.rpc.RpcServer  Rpc server will listen on port 19070
[2021-04-29 12:14:01.846] INFO    : configserver     Container.com.yahoo.container.jdisc.state.StateMonitor Changing health status code from 'initializing' to 'up'
[2021-04-29 12:14:02.017] INFO    : configserver     Container.com.yahoo.vespa.service.duper.DuperModelManager  All infrastructure applications have been activated
[2021-04-29 12:14:02.230] INFO    : configserver     Container.org.eclipse.jetty.server.Server  jetty-9.4.40.v20210413; built: 2021-04-13T20:42:42.668Z; git: b881a572662e1943a14ae12e7e1207989f218b74; jvm 11.0.5+10-LTS
[2021-04-29 12:14:02.271] INFO    : configserver     Container.org.eclipse.jetty.server.handler.ContextHandler  Started o.e.j.s.ServletContextHandler@4055975d{19071,/,null,AVAILABLE}
[2021-04-29 12:14:02.293] INFO    : configserver     Container.org.eclipse.jetty.server.AbstractConnector   Started configserver@67c2b55d{HTTP/1.1, (http/1.1)}{0.0.0.0:19071}
[2021-04-29 12:14:02.294] INFO    : configserver     Container.org.eclipse.jetty.server.Server  Started @16206ms
[2021-04-29 12:14:02.298] INFO    : configserver     Container.com.yahoo.container.jdisc.ConfiguredApplication  Switching to the latest deployed set of configurations and components. Application config generation: 0
abhimech001 commented 3 years ago

to take your last question first: You can't do readiness probe on a fixed port on the content servers. Note that the container server @8080 will monitor the content nodes for the purposes of sending search requests, and there's also a cluster controller which monitors the storage layer on the content node for data feeding and recovering redundancy if necessary. To manually check health you could also run (inside the content node) something like this:

$ vespa-model-inspect host `hostname` 
...
storagenode @ c7-2.build.vespa.dev : content
search/storage/0
    tcp/c7-2.build.vespa.dev:19103 (MESSAGING)
    tcp/c7-2.build.vespa.dev:19104 (STATUS RPC)
    tcp/c7-2.build.vespa.dev:19105 (STATE STATUS HTTP)
searchnode @ c7-2.build.vespa.dev : search
search/search/cluster.search/0
    tcp/c7-2.build.vespa.dev:19106 (STATUS ADMIN RTC RPC)
    tcp/c7-2.build.vespa.dev:19107 (UNUSED)
    tcp/c7-2.build.vespa.dev:19108 (UNUSED)
    tcp/c7-2.build.vespa.dev:19109 (UNUSED)
    tcp/c7-2.build.vespa.dev:19110 (STATE HEALTH JSON HTTP)

$ curl http://c7-2.build.vespa.dev:19105/state/v1/health ; echo
{"status":{"code":"up"}}
$ curl http://c7-2.build.vespa.dev:19110/state/v1/health ; echo
{"status":{"code":"up"}}

regarding your configserver:

sounds like the configserver has way too little resources available. Is this running in AWS or do you have some other kind of setup? What kind of resources (memory/cpu) do you allocate for configserver? my first guess is that there's not enough memory allocated.

this is a typical log sample for me when I just start the configserver. Note the -Xmx2048m option to java which means it will use 2GB of java heap memory.

[arnej@c7-1 vespa]$ vespa-logfmt -l all | head
[2021-04-29 12:13:46.105] EVENT   : configserver     runserver    starting/1 name="java -Xms128m -Xmx2048m -XX:+PreserveFramePointer -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/arnej/vespa/var/crash -XX:ErrorFile=/home/arnej/vespa/var/crash/hs_err_pid%p.log -XX:+ExitOnOutOfMemoryError -XX:-OmitStackTraceInFastThrow --illegal-access=warn --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.net=ALL-UNNAMED --add-opens=java.base/jdk.internal.loader=ALL-UNNAMED -Djava.io.tmpdir=/home/arnej/vespa/tmp -Djava.library.path=/home/arnej/vespa/lib64 -Djava.awt.headless=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.net.client.defaultConnectTimeout=5000 -Dsun.net.client.defaultReadTimeout=60000 -Djavax.net.ssl.keyStoreType=JKS -Djdk.tls.rejectClientInitiatedRenegotiation=true -Djdisc.config.file=/home/arnej/vespa/var/jdisc_container/configserver.properties -Djdisc.export.packages= -Djdisc.cache.path=/home/arnej/vespa/var/vespa/bundlecache/configserver -Djdisc.debug.resources=false -Djdisc.bundle.path=/home/arnej/vespa/lib/jars -Djdisc.logger.enabled=true -Djdisc.logger.level=ALL -Djdisc.logger.tag=jdisc/configserver -Dfile.encoding=UTF-8 -Dzookeeper_log_file_prefix=/home/arnej/vespa/logs/vespa/zookeeper.configserver -cp /home/arnej/vespa/lib/jars/jdisc_core-jar-with-dependencies.jar com.yahoo.jdisc.core.StandaloneMain standalone-container-jar-with-dependencies.jar (pid 55191)"
[2021-04-29 12:13:46.710] DEBUG   : configserver     stdout   Initializing application without privileges.
[2021-04-29 12:13:46.880] INFO    : jdisc/configserver org.apache.felix.framework ServiceEvent REGISTERED
[2021-04-29 12:13:46.882] DEBUG   : jdisc/configserver /com.yahoo.jdisc.core.ApplicationLoader    App location is not a class name. Installing bundle
[2021-04-29 12:13:46.919] DEBUG   : jdisc/configserver /com.yahoo.jdisc.core.FelixFramework   Installing OSGi bundle from 'file:/home/arnej/vespa/lib/jars/standalone-container-jar-with-dependencies.jar'.
[2021-04-29 12:13:46.933] INFO    : jdisc/configserver standalone-container   BundleEvent INSTALLED
[2021-04-29 12:13:46.947] DEBUG   : jdisc/configserver /com.yahoo.jdisc.core.FelixFramework   OSGi bundle 'standalone-container' requires install from 'configdefinitions-jar-with-dependencies.jar'.
[2021-04-29 12:13:46.947] DEBUG   : jdisc/configserver /com.yahoo.jdisc.core.FelixFramework   Installing OSGi bundle from 'file:/home/arnej/vespa/lib/jars/configdefinitions-jar-with-dependencies.jar'.
[2021-04-29 12:13:46.951] INFO    : jdisc/configserver configdefinitions  BundleEvent INSTALLED
[2021-04-29 12:13:46.951] DEBUG   : jdisc/configserver /com.yahoo.jdisc.core.FelixFramework   OSGi bundle 'standalone-container' requires install from 'config-provisioning-jar-with-dependencies.jar'.
[arnej@c7-1 vespa]$ vespa-logfmt -l all | grep Starting.container
[2021-04-29 12:13:49.034] INFO    : configserver     Container.com.yahoo.container.jdisc.ConfiguredApplication    Starting container
[arnej@c7-1 vespa]$ vespa-logfmt -l all | tail
[2021-04-29 12:14:01.619] INFO    : configserver     Container.com.yahoo.vespa.config.server.SuperModelManager    Super model is complete
[2021-04-29 12:14:01.621] INFO    : configserver     Container.com.yahoo.vespa.service.duper.DuperModelManager    All bootstrap tenant applications have been activated
[2021-04-29 12:14:01.836] INFO    : configserver     Container.com.yahoo.vespa.config.server.rpc.RpcServer    Rpc server will listen on port 19070
[2021-04-29 12:14:01.846] INFO    : configserver     Container.com.yahoo.container.jdisc.state.StateMonitor   Changing health status code from 'initializing' to 'up'
[2021-04-29 12:14:02.017] INFO    : configserver     Container.com.yahoo.vespa.service.duper.DuperModelManager    All infrastructure applications have been activated
[2021-04-29 12:14:02.230] INFO    : configserver     Container.org.eclipse.jetty.server.Server    jetty-9.4.40.v20210413; built: 2021-04-13T20:42:42.668Z; git: b881a572662e1943a14ae12e7e1207989f218b74; jvm 11.0.5+10-LTS
[2021-04-29 12:14:02.271] INFO    : configserver     Container.org.eclipse.jetty.server.handler.ContextHandler    Started o.e.j.s.ServletContextHandler@4055975d{19071,/,null,AVAILABLE}
[2021-04-29 12:14:02.293] INFO    : configserver     Container.org.eclipse.jetty.server.AbstractConnector Started configserver@67c2b55d{HTTP/1.1, (http/1.1)}{0.0.0.0:19071}
[2021-04-29 12:14:02.294] INFO    : configserver     Container.org.eclipse.jetty.server.Server    Started @16206ms
[2021-04-29 12:14:02.298] INFO    : configserver     Container.com.yahoo.container.jdisc.ConfiguredApplication    Switching to the latest deployed set of configurations and components. Application config generation: 0

Thank you!!!

Regarding configserver The resource allocated to pod yaml of config server Memory in fixed mode of 4Gi and CPU in burst mode from 1 to 2 cores. Is it enough or it requires more ?

abhimech001 commented 3 years ago

Updated resource of config server Memory : 8Gi to 8Gi CPU : 1 core to 2 Core Time taken to start config server : 851567ms As stated earlier, for first 5-7 mins service jdisc/configserver installed/resolved/started 100's of components and then once configserver Rpc server will listen on port 19070 is detected the configserver starts.

The yaml file picked is from basic search on GKE https://github.com/vespa-engine/sample-apps/blob/master/basic-search-on-gke/deployments/master.yml

Also, we have moved /opt/vespa/var to a symbolic link to a network storage for persistent volume. Can this lead to higher bootup time?

arnej27959 commented 3 years ago

so you're running this in the google cloud? sounds like my guess about memory was wrong; 4GB should be enough to start configserver without any huge delays.

the virtual/network disk is the next suspect, as you say. a clean start of empty configserver writes ~430MB to /opt/vespa/var/vespa/bundlecache here, which takes very little time on my local SSD of course.

abhimech001 commented 3 years ago

so you're running this in the google cloud? sounds like my guess about memory was wrong; 4GB should be enough to start configserver without any huge delays.

the virtual/network disk is the next suspect, as you say. a clean start of empty configserver writes ~430MB to /opt/vespa/var/vespa/bundlecache here, which takes very little time on my local SSD of course.

I have checked the performance of NAS wrt emptyDir{} and it is 3 times slower but still do not account to the start up time I mentioned above. Also, have used NAS with symbolic link to /opt/vespa/var.

baldersheim commented 3 years ago

If you are running this with NAS on google cloud, you might be experiencing the same as we did with the content nodes on Amazon EBS volumes. The feed performance dropped by a factor of 60 when using EBS over local disk. This was caused by using OSYNC. That can be controlled for the content nodes.

However in the configserver I suspect that we do not have control over that as we use zookeeper. @hmusum Do you know if we have any control of wether we use OSYNC for writes in the configserver ?

hmusum commented 3 years ago

ZooKeeper, which Vespa uses as distributed storage for some of the data in the config system, uses fsync to make sure data is written to the file system before giving a successful response for writes. This makes it very sensitive to slow I/O operations and may be what you are experiencing here.

Check if there are log message that include .org.apache.zookeeper.server.persistence.FileTxnLog warning fsync-ing the write ahead log in SyncThread:1 took XXXXms which will adversely effect operation latency in log file /opt/vespa/logs/vespa/zookeeper.configserver.0.log

abhimech001 commented 3 years ago

ZooKeeper, which Vespa uses as distributed storage for some of the data in the config system, uses fsync to make sure data is written to the file system before giving a successful response for writes. This makes it very sensitive to slow I/O operations and may be what you are experiencing here.

Check if there are log message that include .org.apache.zookeeper.server.persistence.FileTxnLog warning fsync-ing the write ahead log in SyncThread:1 took XXXXms which will adversely effect operation latency in log file /opt/vespa/logs/vespa/zookeeper.configserver.0.log

Can find the above log lines in zookeeper log file couple of times with 1003ms and 2142ms.

hmusum commented 3 years ago

Can find the above log lines in zookeeper log file couple of times with 1003ms and 2142ms.

That doesn't sound too bad and does not explain why it takes over 10 minutes to start the config server. If you could share some log from vespa.log (from start up to Switching to the latest deployed set of configurations and components we might be able to understand more

test-forum commented 3 years ago

Adding logs on abhimech001's behalf:

[2021-05-06 12:27:01] EVENT : configserver runserver starting/1 name="java -Xms128m -Xmx2048m -XX:+PreserveFramePointer -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/vespa/var/crash -XX:ErrorFile=/opt/vespa/var/crash/hs_err_pid%p.log -XX:+ExitOnOutOfMemoryError -XX:-OmitStackTraceInFastThrow -XX:MaxJavaStackTraceDepth=1000000 --illegal-access=warn --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.net=ALL-UNNAMED --add-opens=java.base/jdk.internal.loader=ALL-UNNAMED -Djava.io.tmpdir=/opt/vespa/tmp -Djava.library.path=/opt/vespa/lib64 -Djava.awt.headless=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.net.client.defaultConnectTimeout=5000 -Dsun.net.client.defaultReadTimeout=60000 -Djavax.net.ssl.keyStoreType=JKS -Djdk.tls.rejectClientInitiatedRenegotiation=true -Djdisc.config.file=/opt/vespa/var/jdisc_container/configserver.properties -Djdisc.export.packages= -Djdisc.cache.path=/opt/vespa/var/vespa/bundlecache/configserver -Djdisc.debug.resources=false -Djdisc.bundle.path=/opt/vespa/lib/jars -Djdisc.logger.enabled=true -Djdisc.logger.level=ALL -Djdisc.logger.tag=jdisc/configserver -Dfile.encoding=UTF-8 -Dzookeeper_log_file_prefix=/opt/vespa/logs/vespa/zookeeper.configserver -cp /opt/vespa/lib/jars/jdisc_core-jar-with-dependencies.jar com.yahoo.jdisc.core.StandaloneMain standalone-container-jar-with-dependencies.jar (pid 489)" [2021-05-06 12:27:11] EVENT : configproxy runserver starting/1 name="java -Xms32M -Xmx256M -XX:CompressedClassSpaceSize=32m -XX:MaxDirectMemorySize=32m -XX:ThreadStackSize=256 -XX:MaxJavaStackTraceDepth=1000 -XX:-OmitStackTraceInFastThrow -XX:+ExitOnOutOfMemoryError -Dproxyconfigsources=tcp/vespa-0.vespa-internal.default.svc.cluster.local:19070,tcp/vespa-1.vespa-internal.default.svc.cluster.local:19070,tcp/vespa-2.vespa-internal.default.svc.cluster.local:19070 -Djava.io.tmpdir=/opt/vespa/tmp -XX:ActiveProcessorCount=2 -cp libexec/vespa/patches/configproxy:lib/jars/config-proxy-jar-with-dependencies.jar com.yahoo.vespa.config.proxy.ProxyServer 19090 (pid 643)" [2021-05-06 12:27:12] EVENT : configproxy configproxy.com.yahoo.vespa.config.proxy.ProxyServer started/1 name=configproxy [2021-05-06 12:27:28] EVENT : config-sentinel runserver starting/1 name="sbin/vespa-config-sentinel -c hosts/vespa-2.vespa-internal.default.svc.cluster.local (pid 847)" [2021-05-06 12:27:51] EVENT : config-sentinel config-sentinel started/1 name="config-sentinel" [2021-05-06 12:27:51] INFO : configproxy configproxy.com.yahoo.vespa.config Connecting to tcp/vespa-1.vespa-internal.default.svc.cluster.local:19070 [2021-05-06 12:27:51] CONFIG : config-sentinel config-sentinel.rpcserver listening on port 19097 [2021-05-06 12:27:51] EVENT : config-sentinel config-sentinel.service starting/1 name="slobrok" [2021-05-06 12:27:52] EVENT : config-sentinel config-sentinel.service starting/1 name="container-clustercontroller" [2021-05-06 12:27:52] EVENT : config-sentinel config-sentinel.service starting/1 name="metricsproxy-container" [2021-05-06 12:27:52] EVENT : config-sentinel config-sentinel.service starting/1 name="logd" [2021-05-06 12:28:15] EVENT : logd logdemon started/1 name="logdemon" [2021-05-06 12:28:15] INFO : logd logdemon state server listening on port 19089 [2021-05-06 12:28:19] CONFIG : slobrok vespa-slobrok.sbenv listening on port 19099 [2021-05-06 12:28:19] CONFIG : slobrok vespa-slobrok.sbenv added peer tcp/vespa-0.vespa-internal.default.svc.cluster.local:19099 [2021-05-06 12:28:19] CONFIG : slobrok vespa-slobrok.sbenv added peer tcp/vespa-1.vespa-internal.default.svc.cluster.local:19099 [2021-05-06 12:28:19] CONFIG : slobrok vespa-slobrok.sbenv added peer tcp/vespa-container-0.vespa-internal.default.svc.cluster.local:19099 [2021-05-06 12:28:19] CONFIG : slobrok vespa-slobrok.sbenv added peer tcp/vespa-container-1.vespa-internal.default.svc.cluster.local:19099 [2021-05-06 12:28:19] CONFIG : slobrok vespa-slobrok.sbenv added peer tcp/vespa-container-2.vespa-internal.default.svc.cluster.local:19099 [2021-05-06 12:28:20] CONFIG : slobrok vespa-slobrok.sbenv added peer tcp/vespa-content-0.vespa-internal.default.svc.cluster.local:19099 [2021-05-06 12:28:20] CONFIG : slobrok vespa-slobrok.sbenv added peer tcp/vespa-content-1.vespa-internal.default.svc.cluster.local:19099 [2021-05-06 12:28:20] CONFIG : slobrok vespa-slobrok.sbenv added peer tcp/vespa-content-2.vespa-internal.default.svc.cluster.local:19099 [2021-05-06 12:28:20] EVENT : slobrok vespa-slobrok.sbenv started/1 name="slobrok" [2021-05-06 12:28:20] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="heartbeats_failed" value=0 [2021-05-06 12:28:20] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="register_reqs" value=0 [2021-05-06 12:28:21] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="mirror_reqs" value=0 [2021-05-06 12:28:21] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="wantadd_reqs" value=0 [2021-05-06 12:28:21] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doadd_reqs" value=0 [2021-05-06 12:28:21] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doremove_reqs" value=0 [2021-05-06 12:28:21] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="admin_reqs" value=0 [2021-05-06 12:28:22] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="other_reqs" value=0 [2021-05-06 12:29:30] INFO : jdisc/configserver org.apache.felix.framework ServiceEvent REGISTERED [2021-05-06 12:29:32] INFO : jdisc/configserver standalone-container BundleEvent INSTALLED [2021-05-06 12:29:34] INFO : jdisc/configserver configdefinitions BundleEvent INSTALLED [2021-05-06 12:29:36] INFO : jdisc/configserver config-provisioning BundleEvent INSTALLED [2021-05-06 12:29:38] INFO : jdisc/configserver config-bundle BundleEvent INSTALLED [2021-05-06 12:29:40] INFO : jdisc/configserver config-model-api BundleEvent INSTALLED [2021-05-06 12:29:42] INFO : jdisc/configserver config-model BundleEvent INSTALLED [2021-05-06 12:29:45] INFO : jdisc/configserver container-disc BundleEvent INSTALLED [2021-05-06 12:29:46] INFO : jdisc/configserver configgen BundleEvent INSTALLED [2021-05-06 12:29:48] INFO : jdisc/configserver container-jersey2 BundleEvent INSTALLED [2021-05-06 12:29:51] INFO : jdisc/configserver container-search-and-docproc BundleEvent INSTALLED [2021-05-06 12:29:53] INFO : jdisc/configserver container-search-gui BundleEvent INSTALLED [2021-05-06 12:29:54] INFO : jdisc/configserver docprocs BundleEvent INSTALLED [2021-05-06 12:29:56] INFO : jdisc/configserver hosted-zone-api BundleEvent INSTALLED [2021-05-06 12:29:58] INFO : jdisc/configserver jdisc-security-filters BundleEvent INSTALLED [2021-05-06 12:30:00] INFO : jdisc/configserver model-evaluation BundleEvent INSTALLED [2021-05-06 12:30:04] INFO : jdisc/configserver model-integration BundleEvent INSTALLED [2021-05-06 12:30:07] INFO : jdisc/configserver vespaclient-container-plugin BundleEvent INSTALLED [2021-05-06 12:30:09] INFO : jdisc/configserver vespa-athenz BundleEvent INSTALLED [2021-05-06 12:30:11] INFO : jdisc/configserver security-utils BundleEvent INSTALLED [2021-05-06 12:30:13] INFO : jdisc/configserver defaults BundleEvent INSTALLED [2021-05-06 12:30:15] INFO : jdisc/configserver zkfacade BundleEvent INSTALLED [2021-05-06 12:30:18] INFO : jdisc/configserver zookeeper-server BundleEvent INSTALLED [2021-05-06 12:30:19] INFO : jdisc/configserver org.eclipse.jetty.alpn.api BundleEvent INSTALLED [2021-05-06 12:30:21] INFO : jdisc/configserver org.eclipse.jetty.http2.server BundleEvent INSTALLED [2021-05-06 12:30:23] INFO : jdisc/configserver org.eclipse.jetty.http2.common BundleEvent INSTALLED [2021-05-06 12:30:25] INFO : jdisc/configserver org.eclipse.jetty.http2.hpack BundleEvent INSTALLED [2021-05-06 12:30:27] INFO : jdisc/configserver org.eclipse.jetty.alpn.java.server BundleEvent INSTALLED [2021-05-06 12:30:29] INFO : jdisc/configserver org.eclipse.jetty.alpn.server BundleEvent INSTALLED [2021-05-06 12:30:30] INFO : jdisc/configserver org.eclipse.jetty.continuation BundleEvent INSTALLED [2021-05-06 12:30:32] INFO : jdisc/configserver org.eclipse.jetty.http BundleEvent INSTALLED [2021-05-06 12:30:34] INFO : jdisc/configserver org.eclipse.jetty.io BundleEvent INSTALLED [2021-05-06 12:30:36] INFO : jdisc/configserver org.eclipse.jetty.jmx BundleEvent INSTALLED [2021-05-06 12:30:38] INFO : jdisc/configserver org.eclipse.jetty.security BundleEvent INSTALLED [2021-05-06 12:30:40] INFO : jdisc/configserver org.eclipse.jetty.server BundleEvent INSTALLED [2021-05-06 12:30:41] INFO : jdisc/configserver org.eclipse.jetty.servlet BundleEvent INSTALLED [2021-05-06 12:30:43] INFO : jdisc/configserver org.eclipse.jetty.servlets BundleEvent INSTALLED [2021-05-06 12:30:45] INFO : jdisc/configserver org.eclipse.jetty.util BundleEvent INSTALLED [2021-05-06 12:30:47] INFO : jdisc/configserver org.eclipse.jetty.util.ajax BundleEvent INSTALLED [2021-05-06 12:30:49] INFO : jdisc/configserver org.apache.aries.spifly.dynamic.bundle BundleEvent INSTALLED [2021-05-06 12:30:50] INFO : jdisc/configserver org.objectweb.asm BundleEvent INSTALLED [2021-05-06 12:30:52] INFO : jdisc/configserver org.objectweb.asm.tree.analysis BundleEvent INSTALLED [2021-05-06 12:30:54] INFO : jdisc/configserver org.objectweb.asm.commons BundleEvent INSTALLED [2021-05-06 12:30:56] INFO : jdisc/configserver org.objectweb.asm.tree BundleEvent INSTALLED [2021-05-06 12:30:57] INFO : jdisc/configserver org.objectweb.asm.util BundleEvent INSTALLED [2021-05-06 12:31:00] INFO : jdisc/configserver bcpkix BundleEvent INSTALLED [2021-05-06 12:31:02] INFO : jdisc/configserver bcprov BundleEvent INSTALLED [2021-05-06 12:31:04] INFO : jdisc/configserver javax.servlet-api BundleEvent INSTALLED [2021-05-06 12:31:05] INFO : jdisc/configserver org.glassfish.hk2.external.aopalliance-repackaged BundleEvent INSTALLED [2021-05-06 12:31:07] INFO : jdisc/configserver org.glassfish.hk2.api BundleEvent INSTALLED [2021-05-06 12:31:09] INFO : jdisc/configserver org.glassfish.hk2.locator BundleEvent INSTALLED [2021-05-06 12:31:11] INFO : jdisc/configserver org.glassfish.hk2.utils BundleEvent INSTALLED [2021-05-06 12:31:12] INFO : jdisc/configserver com.fasterxml.jackson.core.jackson-annotations BundleEvent INSTALLED [2021-05-06 12:31:15] INFO : jdisc/configserver com.fasterxml.jackson.core.jackson-core BundleEvent INSTALLED [2021-05-06 12:31:17] INFO : jdisc/configserver com.fasterxml.jackson.core.jackson-databind BundleEvent INSTALLED [2021-05-06 12:31:18] INFO : jdisc/configserver com.fasterxml.jackson.datatype.jackson-datatype-jdk8 BundleEvent INSTALLED [2021-05-06 12:31:20] INFO : jdisc/configserver com.fasterxml.jackson.datatype.jackson-datatype-jsr310 BundleEvent INSTALLED [2021-05-06 12:31:22] INFO : jdisc/configserver com.fasterxml.jackson.jaxrs.jackson-jaxrs-base BundleEvent INSTALLED [2021-05-06 12:31:24] INFO : jdisc/configserver com.fasterxml.jackson.jaxrs.jackson-jaxrs-json-provider BundleEvent INSTALLED [2021-05-06 12:31:25] INFO : jdisc/configserver com.fasterxml.jackson.module.jackson-module-jaxb-annotations BundleEvent INSTALLED [2021-05-06 12:31:27] INFO : jdisc/configserver jakarta.activation-api BundleEvent INSTALLED [2021-05-06 12:31:29] INFO : jdisc/configserver jakarta.xml.bind-api BundleEvent INSTALLED [2021-05-06 12:31:31] INFO : jdisc/configserver javassist BundleEvent INSTALLED [2021-05-06 12:31:33] INFO : jdisc/configserver javax.ws.rs-api BundleEvent INSTALLED [2021-05-06 12:31:34] INFO : jdisc/configserver org.glassfish.jersey.core.jersey-client BundleEvent INSTALLED [2021-05-06 12:31:36] INFO : jdisc/configserver org.glassfish.jersey.core.jersey-common BundleEvent INSTALLED [2021-05-06 12:31:38] INFO : jdisc/configserver org.glassfish.jersey.containers.jersey-container-servlet BundleEvent INSTALLED [2021-05-06 12:31:40] INFO : jdisc/configserver org.glassfish.jersey.containers.jersey-container-servlet-core BundleEvent INSTALLED [2021-05-06 12:31:42] INFO : jdisc/configserver org.glassfish.jersey.ext.jersey-entity-filtering BundleEvent INSTALLED [2021-05-06 12:31:44] INFO : jdisc/configserver org.glassfish.jersey.bundles.repackaged.jersey-guava BundleEvent INSTALLED [2021-05-06 12:31:45] INFO : jdisc/configserver org.glassfish.jersey.media.jersey-media-jaxb BundleEvent INSTALLED [2021-05-06 12:31:47] INFO : jdisc/configserver org.glassfish.jersey.media.jersey-media-json-jackson BundleEvent INSTALLED [2021-05-06 12:31:49] INFO : jdisc/configserver org.glassfish.jersey.media.jersey-media-multipart BundleEvent INSTALLED [2021-05-06 12:31:50] INFO : jdisc/configserver org.jvnet.mimepull BundleEvent INSTALLED [2021-05-06 12:31:53] INFO : jdisc/configserver org.glassfish.jersey.core.jersey-server BundleEvent INSTALLED [2021-05-06 12:31:54] INFO : jdisc/configserver org.glassfish.jersey.ext.jersey-proxy-client BundleEvent INSTALLED [2021-05-06 12:31:56] INFO : jdisc/configserver org.glassfish.hk2.osgi-resource-locator BundleEvent INSTALLED [2021-05-06 12:31:58] INFO : jdisc/configserver javax.validation.api BundleEvent INSTALLED [2021-05-06 12:32:00] INFO : jdisc/configserver vespajlib BundleEvent INSTALLED [2021-05-06 12:32:01] INFO : jdisc/configserver model-evaluation BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver com.fasterxml.jackson.core.jackson-databind BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.http BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.objectweb.asm BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver config-model-api BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.util.ajax BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.alpn.api BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.alpn.java.server BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver jdisc-security-filters BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.objectweb.asm.tree BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.http2.hpack BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.server BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.util BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.objectweb.asm.tree.analysis BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.servlet BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver container-search-and-docproc BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.objectweb.asm.commons BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver configdefinitions BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver bcprov BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver vespa-athenz BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver container-disc BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver config-model BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver com.fasterxml.jackson.core.jackson-core BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver config-bundle BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver config-provisioning BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.http2.server BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver com.fasterxml.jackson.datatype.jackson-datatype-jdk8 BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.http2.common BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver hosted-zone-api BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.io BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.jmx BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver bcpkix BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver javax.servlet-api BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver com.fasterxml.jackson.datatype.jackson-datatype-jsr310 BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver com.fasterxml.jackson.core.jackson-annotations BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.apache.aries.spifly.dynamic.bundle BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver standalone-container BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.alpn.server BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.objectweb.asm.util BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver org.eclipse.jetty.security BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver model-integration BundleEvent RESOLVED [2021-05-06 12:32:01] INFO : jdisc/configserver standalone-container BundleEvent STARTED [2021-05-06 12:32:01] INFO : jdisc/configserver configdefinitions BundleEvent STARTED [2021-05-06 12:32:02] INFO : jdisc/configserver config-provisioning BundleEvent STARTED [2021-05-06 12:32:02] INFO : jdisc/configserver config-bundle BundleEvent STARTED [2021-05-06 12:32:02] INFO : jdisc/configserver config-model-api BundleEvent STARTED [2021-05-06 12:32:03] INFO : jdisc/configserver config-model BundleEvent STARTED [2021-05-06 12:32:03] INFO : jdisc/configserver container-disc BundleEvent STARTED [2021-05-06 12:32:04] INFO : jdisc/configserver configgen BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver configgen BundleEvent STARTED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.jersey.media.jersey-media-multipart BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver com.fasterxml.jackson.jaxrs.jackson-jaxrs-base BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.hk2.external.aopalliance-repackaged BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.hk2.osgi-resource-locator BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.hk2.locator BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver javax.ws.rs-api BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver com.fasterxml.jackson.module.jackson-module-jaxb-annotations BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.hk2.api BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver javax.validation.api BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.jersey.core.jersey-common BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver container-jersey2 BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.jersey.core.jersey-client BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.jersey.bundles.repackaged.jersey-guava BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.hk2.utils BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.jvnet.mimepull BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.jersey.containers.jersey-container-servlet-core BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver org.glassfish.jersey.core.jersey-server BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver com.fasterxml.jackson.jaxrs.jackson-jaxrs-json-provider BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver javassist BundleEvent RESOLVED [2021-05-06 12:32:04] INFO : jdisc/configserver container-jersey2 BundleEvent STARTED [2021-05-06 12:32:05] INFO : jdisc/configserver container-search-and-docproc BundleEvent STARTED [2021-05-06 12:32:05] INFO : jdisc/configserver container-search-gui BundleEvent RESOLVED [2021-05-06 12:32:05] INFO : jdisc/configserver container-search-gui BundleEvent STARTED [2021-05-06 12:32:05] INFO : jdisc/configserver docprocs BundleEvent RESOLVED [2021-05-06 12:32:05] INFO : jdisc/configserver docprocs BundleEvent STARTED [2021-05-06 12:32:06] INFO : jdisc/configserver hosted-zone-api BundleEvent STARTED [2021-05-06 12:32:06] INFO : jdisc/configserver jdisc-security-filters BundleEvent STARTED [2021-05-06 12:32:07] INFO : jdisc/configserver model-evaluation BundleEvent STARTED [2021-05-06 12:32:07] INFO : jdisc/configserver model-integration BundleEvent STARTED [2021-05-06 12:32:08] INFO : jdisc/configserver vespaclient-container-plugin BundleEvent RESOLVED [2021-05-06 12:32:08] INFO : jdisc/configserver vespaclient-container-plugin BundleEvent STARTED [2021-05-06 12:32:08] INFO : jdisc/configserver vespa-athenz BundleEvent STARTED [2021-05-06 12:32:08] INFO : jdisc/configserver security-utils BundleEvent RESOLVED [2021-05-06 12:32:08] INFO : jdisc/configserver security-utils BundleEvent STARTED [2021-05-06 12:32:09] INFO : jdisc/configserver defaults BundleEvent RESOLVED [2021-05-06 12:32:09] INFO : jdisc/configserver defaults BundleEvent STARTED [2021-05-06 12:32:09] INFO : jdisc/configserver zookeeper-server BundleEvent RESOLVED [2021-05-06 12:32:09] INFO : jdisc/configserver zkfacade BundleEvent RESOLVED [2021-05-06 12:32:09] INFO : jdisc/configserver zkfacade BundleEvent STARTED [2021-05-06 12:32:10] INFO : jdisc/configserver zookeeper-server BundleEvent STARTED [2021-05-06 12:32:10] INFO : jdisc/configserver org.eclipse.jetty.alpn.api BundleEvent STARTED [2021-05-06 12:32:11] INFO : jdisc/configserver org.eclipse.jetty.http2.server BundleEvent STARTED [2021-05-06 12:32:11] INFO : jdisc/configserver org.eclipse.jetty.http2.common BundleEvent STARTED [2021-05-06 12:32:11] INFO : jdisc/configserver org.eclipse.jetty.http2.hpack BundleEvent STARTED [2021-05-06 12:32:12] INFO : jdisc/configserver org.eclipse.jetty.alpn.java.server BundleEvent STARTED [2021-05-06 12:32:12] INFO : jdisc/configserver org.eclipse.jetty.alpn.server BundleEvent STARTED [2021-05-06 12:32:13] INFO : jdisc/configserver org.eclipse.jetty.continuation BundleEvent RESOLVED [2021-05-06 12:32:13] INFO : jdisc/configserver org.eclipse.jetty.continuation BundleEvent STARTED [2021-05-06 12:32:13] INFO : jdisc/configserver org.eclipse.jetty.http BundleEvent STARTED [2021-05-06 12:32:14] INFO : jdisc/configserver org.eclipse.jetty.io BundleEvent STARTED [2021-05-06 12:32:14] INFO : jdisc/configserver org.eclipse.jetty.jmx BundleEvent STARTED [2021-05-06 12:32:14] INFO : jdisc/configserver org.eclipse.jetty.security BundleEvent STARTED [2021-05-06 12:32:15] INFO : jdisc/configserver org.eclipse.jetty.server BundleEvent STARTED [2021-05-06 12:32:15] INFO : jdisc/configserver org.eclipse.jetty.servlet BundleEvent STARTED [2021-05-06 12:32:16] INFO : jdisc/configserver org.eclipse.jetty.servlets BundleEvent RESOLVED [2021-05-06 12:32:16] INFO : jdisc/configserver org.eclipse.jetty.servlets BundleEvent STARTED [2021-05-06 12:32:16] INFO : jdisc/configserver org.eclipse.jetty.util BundleEvent STARTED [2021-05-06 12:32:17] INFO : jdisc/configserver org.eclipse.jetty.util.ajax BundleEvent STARTED [2021-05-06 12:32:17] INFO : jdisc/configserver org.apache.aries.spifly.dynamic.bundle ServiceEvent REGISTERED [2021-05-06 12:32:17] INFO : jdisc/configserver org.eclipse.jetty.http2.hpack ServiceEvent REGISTERED [2021-05-06 12:32:17] INFO : jdisc/configserver /org.apache.aries.spifly.BaseActivator Registered provider org.eclipse.jetty.http2.hpack.HpackFieldPreEncoder of service org.eclipse.jetty.http.HttpFieldPreEncoder in bundle org.eclipse.jetty.http2.hpack [2021-05-06 12:32:18] INFO : jdisc/configserver /org.eclipse.jetty.util.log Logging initialized @316836ms to org.eclipse.jetty.util.log.Slf4jLog [2021-05-06 12:32:18] INFO : jdisc/configserver org.eclipse.jetty.alpn.java.server ServiceEvent REGISTERED [2021-05-06 12:32:18] INFO : jdisc/configserver /org.apache.aries.spifly.BaseActivator Registered provider org.eclipse.jetty.alpn.java.server.JDK9ServerALPNProcessor of service org.eclipse.jetty.io.ssl.ALPNProcessor$Server in bundle org.eclipse.jetty.alpn.java.server [2021-05-06 12:32:18] INFO : jdisc/configserver org.eclipse.jetty.http ServiceEvent REGISTERED [2021-05-06 12:32:18] INFO : jdisc/configserver /org.apache.aries.spifly.BaseActivator Registered provider org.eclipse.jetty.http.Http1FieldPreEncoder of service org.eclipse.jetty.http.HttpFieldPreEncoder in bundle org.eclipse.jetty.http [2021-05-06 12:32:18] INFO : jdisc/configserver org.apache.aries.spifly.dynamic.bundle BundleEvent STARTED [2021-05-06 12:32:19] INFO : jdisc/configserver org.objectweb.asm BundleEvent STARTED [2021-05-06 12:32:19] INFO : jdisc/configserver org.objectweb.asm.tree.analysis BundleEvent STARTED [2021-05-06 12:32:20] INFO : jdisc/configserver org.objectweb.asm.commons BundleEvent STARTED [2021-05-06 12:32:20] INFO : jdisc/configserver org.objectweb.asm.tree BundleEvent STARTED [2021-05-06 12:32:20] INFO : jdisc/configserver org.objectweb.asm.util BundleEvent STARTED [2021-05-06 12:32:21] INFO : jdisc/configserver bcpkix BundleEvent STARTED [2021-05-06 12:32:21] INFO : jdisc/configserver bcprov BundleEvent STARTED [2021-05-06 12:32:22] INFO : jdisc/configserver javax.servlet-api BundleEvent STARTED [2021-05-06 12:32:22] INFO : jdisc/configserver org.glassfish.hk2.external.aopalliance-repackaged BundleEvent STARTED [2021-05-06 12:32:23] INFO : jdisc/configserver org.glassfish.hk2.api BundleEvent STARTED [2021-05-06 12:32:23] INFO : jdisc/configserver org.glassfish.hk2.locator BundleEvent STARTED [2021-05-06 12:32:23] INFO : jdisc/configserver org.glassfish.hk2.utils BundleEvent STARTED [2021-05-06 12:32:24] INFO : jdisc/configserver com.fasterxml.jackson.core.jackson-annotations BundleEvent STARTED [2021-05-06 12:32:24] INFO : jdisc/configserver com.fasterxml.jackson.core.jackson-core BundleEvent STARTED [2021-05-06 12:32:25] INFO : jdisc/configserver com.fasterxml.jackson.core.jackson-databind BundleEvent STARTED [2021-05-06 12:32:25] INFO : jdisc/configserver com.fasterxml.jackson.datatype.jackson-datatype-jdk8 BundleEvent STARTED [2021-05-06 12:32:25] INFO : jdisc/configserver com.fasterxml.jackson.datatype.jackson-datatype-jsr310 BundleEvent STARTED [2021-05-06 12:32:26] INFO : jdisc/configserver com.fasterxml.jackson.jaxrs.jackson-jaxrs-base BundleEvent STARTED [2021-05-06 12:32:26] INFO : jdisc/configserver com.fasterxml.jackson.jaxrs.jackson-jaxrs-json-provider BundleEvent STARTED [2021-05-06 12:32:27] INFO : jdisc/configserver com.fasterxml.jackson.module.jackson-module-jaxb-annotations BundleEvent STARTED [2021-05-06 12:32:27] INFO : jdisc/configserver jakarta.activation-api BundleEvent RESOLVED [2021-05-06 12:32:27] INFO : jdisc/configserver jakarta.activation-api BundleEvent STARTED [2021-05-06 12:32:28] INFO : jdisc/configserver jakarta.xml.bind-api BundleEvent RESOLVED [2021-05-06 12:32:28] INFO : jdisc/configserver jakarta.xml.bind-api BundleEvent STARTED [2021-05-06 12:32:28] INFO : jdisc/configserver javassist BundleEvent STARTED [2021-05-06 12:32:28] INFO : jdisc/configserver javax.ws.rs-api BundleEvent STARTED [2021-05-06 12:32:29] INFO : jdisc/configserver org.glassfish.jersey.core.jersey-client BundleEvent STARTED [2021-05-06 12:32:29] INFO : jdisc/configserver org.glassfish.jersey.core.jersey-common BundleEvent STARTED [2021-05-06 12:32:30] INFO : jdisc/configserver org.glassfish.jersey.containers.jersey-container-servlet BundleEvent RESOLVED [2021-05-06 12:32:30] INFO : jdisc/configserver org.glassfish.jersey.containers.jersey-container-servlet BundleEvent STARTED [2021-05-06 12:32:30] INFO : jdisc/configserver org.glassfish.jersey.containers.jersey-container-servlet-core BundleEvent STARTED [2021-05-06 12:32:31] INFO : jdisc/configserver org.glassfish.jersey.ext.jersey-entity-filtering BundleEvent RESOLVED [2021-05-06 12:32:31] INFO : jdisc/configserver org.glassfish.jersey.ext.jersey-entity-filtering BundleEvent STARTED [2021-05-06 12:32:31] INFO : jdisc/configserver org.glassfish.jersey.bundles.repackaged.jersey-guava BundleEvent STARTED [2021-05-06 12:32:31] INFO : jdisc/configserver org.glassfish.jersey.media.jersey-media-jaxb BundleEvent RESOLVED [2021-05-06 12:32:31] INFO : jdisc/configserver org.glassfish.jersey.media.jersey-media-jaxb BundleEvent STARTED [2021-05-06 12:32:32] INFO : jdisc/configserver org.glassfish.jersey.media.jersey-media-json-jackson BundleEvent RESOLVED [2021-05-06 12:32:32] INFO : jdisc/configserver org.glassfish.jersey.media.jersey-media-json-jackson BundleEvent STARTED [2021-05-06 12:32:32] INFO : jdisc/configserver org.glassfish.jersey.media.jersey-media-multipart BundleEvent STARTED [2021-05-06 12:32:33] INFO : jdisc/configserver org.jvnet.mimepull BundleEvent STARTED [2021-05-06 12:32:33] INFO : jdisc/configserver org.glassfish.jersey.core.jersey-server BundleEvent STARTED [2021-05-06 12:32:34] INFO : jdisc/configserver org.glassfish.jersey.ext.jersey-proxy-client BundleEvent RESOLVED [2021-05-06 12:32:34] INFO : jdisc/configserver org.glassfish.jersey.ext.jersey-proxy-client BundleEvent STARTED [2021-05-06 12:32:36] INFO : jdisc/configserver org.glassfish.hk2.osgi-resource-locator BundleEvent STARTED [2021-05-06 12:32:36] INFO : jdisc/configserver javax.validation.api BundleEvent STARTED [2021-05-06 12:32:36] INFO : jdisc/configserver vespajlib BundleEvent RESOLVED [2021-05-06 12:32:36] INFO : jdisc/configserver vespajlib BundleEvent STARTED [2021-05-06 12:32:36] INFO : jdisc/configserver /com.yahoo.jdisc.core.FelixFramework Started bundles: {[1]standalone-container:7.0.0, [2]configdefinitions:7.0.0, [3]config-provisioning:7.0.0, [4]config-bundle:7.0.0, [5]config-model-api:7.0.0, [6]config-model:7.0.0, [7]container-disc:7.0.0, [8]configgen:7.0.0, [9]container-jersey2:7.0.0, [10]container-search-and-docproc:7.0.0, [11]container-search-gui:7.0.0, [12]docprocs:7.0.0, [13]hosted-zone-api:7.0.0, [14]jdisc-security-filters:7.0.0, [15]model-evaluation:7.0.0, [16]model-integration:7.0.0, [17]vespaclient-container-plugin:7.0.0, [18]vespa-athenz:7.0.0, [19]security-utils:7.0.0, [20]defaults:7.0.0, [21]zkfacade:7.0.0, [22]zookeeper-server:7.0.0, [23]org.eclipse.jetty.alpn.api:1.1.3.v20160715, [24]org.eclipse.jetty.http2.server:9.4.40.v20210413, [25]org.eclipse.jetty.http2.common:9.4.40.v20210413, [26]org.eclipse.jetty.http2.hpack:9.4.40.v20210413, [27]org.eclipse.jetty.alpn.java.server:9.4.40.v20210413, [28]org.eclipse.jetty.alpn.server:9.4.40.v20210413, [29]org.eclipse.jetty.continuation:9.4.40.v20210413, [30]org.eclipse.jetty.http:9.4.40.v20210413, [31]org.eclipse.jetty.io:9.4.40.v20210413, [32]org.eclipse.jetty.jmx:9.4.40.v20210413, [33]org.eclipse.jetty.security:9.4.40.v20210413, [34]org.eclipse.jetty.server:9.4.40.v20210413, [35]org.eclipse.jetty.servlet:9.4.40.v20210413, [36]org.eclipse.jetty.servlets:9.4.40.v20210413, [37]org.eclipse.jetty.util:9.4.40.v20210413, [38]org.eclipse.jetty.util.ajax:9.4.40.v20210413, [39]org.apache.aries.spifly.dynamic.bundle:1.3.3, [40]org.objectweb.asm:9.1.0, [41]org.objectweb.asm.tree.analysis:9.1.0, [42]org.objectweb.asm.commons:9.1.0, [43]org.objectweb.asm.tree:9.1.0, [44]org.objectweb.asm.util:9.1.0, [45]bcpkix:1.65.0, [46]bcprov:1.65.0, [47]javax.servlet-api:3.1.0, [48]org.glassfish.hk2.external.aopalliance-repackaged:2.5.0.b32, [49]org.glassfish.hk2.api:2.5.0.b32, [50]org.glassfish.hk2.locator:2.5.0.b32, [51]org.glassfish.hk2.utils:2.5.0.b32, [52]com.fasterxml.jackson.core.jackson-annotations:2.12.1, [53]com.fasterxml.jackson.core.jackson-core:2.12.1, [54]com.fasterxml.jackson.core.jackson-databind:2.12.1, [55]com.fasterxml.jackson.datatype.jackson-datatype-jdk8:2.12.1, [56]com.fasterxml.jackson.datatype.jackson-datatype-jsr310:2.12.1, [57]com.fasterxml.jackson.jaxrs.jackson-jaxrs-base:2.12.1, [58]com.fasterxml.jackson.jaxrs.jackson-jaxrs-json-provider:2.12.1, [59]com.fasterxml.jackson.module.jackson-module-jaxb-annotations:2.12.1, [60]jakarta.activation-api:1.2.1, [61]jakarta.xml.bind-api:2.3.2, [62]javassist:3.20.0.GA, [63]javax.ws.rs-api:2.0.1, [64]org.glassfish.jersey.core.jersey-client:2.25.0, [65]org.glassfish.jersey.core.jersey-common:2.25.0, [66]org.glassfish.jersey.containers.jersey-container-servlet:2.25.0, [67]org.glassfish.jersey.containers.jersey-container-servlet-core:2.25.0, [68]org.glassfish.jersey.ext.jersey-entity-filtering:2.25.0, [69]org.glassfish.jersey.bundles.repackaged.jersey-guava:2.25.0, [70]org.glassfish.jersey.media.jersey-media-jaxb:2.25.0, [71]org.glassfish.jersey.media.jersey-media-json-jackson:2.25.0, [72]org.glassfish.jersey.media.jersey-media-multipart:2.25.0, [73]org.jvnet.mimepull:1.9.6, [74]org.glassfish.jersey.core.jersey-server:2.25.0, [75]org.glassfish.jersey.ext.jersey-proxy-client:2.25.0, [76]org.glassfish.hk2.osgi-resource-locator:1.0.1, [77]javax.validation.api:1.1.0.Final, [78]vespajlib:7.0.0} [2021-05-06 12:33:21] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="heartbeats_failed" value=0 [2021-05-06 12:33:22] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="register_reqs" value=0 [2021-05-06 12:33:22] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="mirror_reqs" value=0 [2021-05-06 12:33:22] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="wantadd_reqs" value=0 [2021-05-06 12:33:22] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doadd_reqs" value=767 [2021-05-06 12:33:22] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doremove_reqs" value=2 [2021-05-06 12:33:22] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="admin_reqs" value=16 [2021-05-06 12:33:23] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="other_reqs" value=8 [2021-05-06 12:33:28] INFO : metricsproxy-container Container.com.yahoo.container.jdisc.ConfiguredApplication Starting container [2021-05-06 12:33:30] INFO : configserver Container.com.yahoo.container.jdisc.ConfiguredApplication Starting container [2021-05-06 12:33:31] INFO : metricsproxy-container Container.com.yahoo.vespa.config Connecting to tcp/localhost:19090 [2021-05-06 12:33:32] INFO : metricsproxy-container Container.com.yahoo.osgi.OsgiImpl Using container-disc [1] to lookup current bundles. [2021-05-06 12:33:33] INFO : metricsproxy-container Container.com.yahoo.container.core.config.PlatformBundleLoader Installing bundle from disk: /opt/vespa/lib/jars/metrics-proxy-jar-with-dependencies.jar [2021-05-06 12:33:36] INFO : metricsproxy-container Container.com.yahoo.container.core.config.HandlersConfigurerDi Installing bundles from the latest application [2021-05-06 12:33:36] INFO : metricsproxy-container Container.com.yahoo.container.core.config.ApplicationBundleLoader Bundles to schedule for uninstall: [] [2021-05-06 12:33:36] INFO : metricsproxy-container Container.com.yahoo.container.core.config.ApplicationBundleLoader Installed bundles: {[0]org.apache.felix.framework:6.0.3, [1]container-disc:7.0.0, [2]configgen:7.0.0, [3]config-bundle:7.0.0, [4]configdefinitions:7.0.0, [5]container-jersey2:7.0.0, [6]container-search-and-docproc:7.0.0, [7]container-search-gui:7.0.0, [8]docprocs:7.0.0, [9]hosted-zone-api:7.0.0, [10]jdisc-security-filters:7.0.0, [11]model-evaluation:7.0.0, [12]model-integration:7.0.0, [13]vespaclient-container-plugin:7.0.0, [14]vespa-athenz:7.0.0, [15]security-utils:7.0.0, [16]defaults:7.0.0, [17]zkfacade:7.0.0, [18]zookeeper-server:7.0.0, [19]org.eclipse.jetty.alpn.api:1.1.3.v20160715, [20]org.eclipse.jetty.http2.server:9.4.40.v20210413, [21]org.eclipse.jetty.http2.common:9.4.40.v20210413, [22]org.eclipse.jetty.http2.hpack:9.4.40.v20210413, [23]org.eclipse.jetty.alpn.java.server:9.4.40.v20210413, [24]org.eclipse.jetty.alpn.server:9.4.40.v20210413, [25]org.eclipse.jetty.continuation:9.4.40.v20210413, [26]org.eclipse.jetty.http:9.4.40.v20210413, [27]org.eclipse.jetty.io:9.4.40.v20210413, [28]org.eclipse.jetty.jmx:9.4.40.v20210413, [29]org.eclipse.jetty.security:9.4.40.v20210413, [30]org.eclipse.jetty.server:9.4.40.v20210413, [31]org.eclipse.jetty.servlet:9.4.40.v20210413, [32]org.eclipse.jetty.servlets:9.4.40.v20210413, [33]org.eclipse.jetty.util:9.4.40.v20210413, [34]org.eclipse.jetty.util.ajax:9.4.40.v20210413, [35]org.apache.aries.spifly.dynamic.bundle:1.3.3, [36]org.objectweb.asm:9.1.0, [37]org.objectweb.asm.tree.analysis:9.1.0, [38]org.objectweb.asm.commons:9.1.0, [39]org.objectweb.asm.tree:9.1.0, [40]org.objectweb.asm.util:9.1.0, [41]bcpkix:1.65.0, [42]bcprov:1.65.0, [43]javax.servlet-api:3.1.0, [44]org.glassfish.hk2.external.aopalliance-repackaged:2.5.0.b32, [45]org.glassfish.hk2.api:2.5.0.b32, [46]org.glassfish.hk2.locator:2.5.0.b32, [47]org.glassfish.hk2.utils:2.5.0.b32, [48]com.fasterxml.jackson.core.jackson-annotations:2.12.1, [49]com.fasterxml.jackson.core.jackson-core:2.12.1, [50]com.fasterxml.jackson.core.jackson-databind:2.12.1, [51]com.fasterxml.jackson.datatype.jackson-datatype-jdk8:2.12.1, [52]com.fasterxml.jackson.datatype.jackson-datatype-jsr310:2.12.1, [53]com.fasterxml.jackson.jaxrs.jackson-jaxrs-base:2.12.1, [54]com.fasterxml.jackson.jaxrs.jackson-jaxrs-json-provider:2.12.1, [55]com.fasterxml.jackson.module.jackson-module-jaxb-annotations:2.12.1, [56]jakarta.activation-api:1.2.1, [57]jakarta.xml.bind-api:2.3.2, [58]javassist:3.20.0.GA, [59]javax.ws.rs-api:2.0.1, [60]org.glassfish.jersey.core.jersey-client:2.25.0, [61]org.glassfish.jersey.core.jersey-common:2.25.0, [62]org.glassfish.jersey.containers.jersey-container-servlet:2.25.0, [63]org.glassfish.jersey.containers.jersey-container-servlet-core:2.25.0, [64]org.glassfish.jersey.ext.jersey-entity-filtering:2.25.0, [65]org.glassfish.jersey.bundles.repackaged.jersey-guava:2.25.0, [66]org.glassfish.jersey.media.jersey-media-jaxb:2.25.0, [67]org.glassfish.jersey.media.jersey-media-json-jackson:2.25.0, [68]org.glassfish.jersey.media.jersey-media-multipart:2.25.0, [69]org.jvnet.mimepull:1.9.6, [70]org.glassfish.jersey.core.jersey-server:2.25.0, [71]org.glassfish.jersey.ext.jersey-proxy-client:2.25.0, [72]org.glassfish.hk2.osgi-resource-locator:1.0.1, [73]javax.validation.api:1.1.0.Final, [74]com.yahoo.vespa.metrics-proxy:7.0.0} [2021-05-06 12:33:37] INFO : container-clustercontroller Container.com.yahoo.container.jdisc.ConfiguredApplication Starting container [2021-05-06 12:33:38] INFO : container-clustercontroller Container.com.yahoo.vespa.config Connecting to tcp/localhost:19090 [2021-05-06 12:33:42] INFO : container-clustercontroller Container.com.yahoo.osgi.OsgiImpl Using container-disc [1] to lookup current bundles. [2021-05-06 12:33:42] INFO : container-clustercontroller Container.com.yahoo.container.core.config.PlatformBundleLoader Installing bundle from disk: /opt/vespa/lib/jars/clustercontroller-apps-jar-with-dependencies.jar [2021-05-06 12:33:44] INFO : container-clustercontroller Container.com.yahoo.container.core.config.PlatformBundleLoader Installing bundle from disk: /opt/vespa/lib/jars/clustercontroller-core-jar-with-dependencies.jar [2021-05-06 12:33:46] INFO : container-clustercontroller Container.com.yahoo.container.core.config.PlatformBundleLoader Installing bundle from disk: /opt/vespa/lib/jars/clustercontroller-reindexer-jar-with-dependencies.jar [2021-05-06 12:33:48] INFO : container-clustercontroller Container.com.yahoo.container.core.config.PlatformBundleLoader Installing bundle from disk: /opt/vespa/lib/jars/clustercontroller-utils-jar-with-dependencies.jar [2021-05-06 12:33:50] INFO : container-clustercontroller Container.com.yahoo.container.core.config.PlatformBundleLoader Installing bundle from disk: /opt/vespa/lib/jars/zookeeper-server-jar-with-dependencies.jar [2021-05-06 12:33:52] INFO : container-clustercontroller Container.com.yahoo.container.core.config.HandlersConfigurerDi Installing bundles from the latest application [2021-05-06 12:33:52] INFO : container-clustercontroller Container.com.yahoo.container.core.config.ApplicationBundleLoader Bundles to schedule for uninstall: [] [2021-05-06 12:33:52] INFO : container-clustercontroller Container.com.yahoo.container.core.config.ApplicationBundleLoader Installed bundles: {[0]org.apache.felix.framework:6.0.3, [1]container-disc:7.0.0, [2]configgen:7.0.0, [3]config-bundle:7.0.0, [4]configdefinitions:7.0.0, [5]container-jersey2:7.0.0, [6]container-search-and-docproc:7.0.0, [7]container-search-gui:7.0.0, [8]docprocs:7.0.0, [9]hosted-zone-api:7.0.0, [10]jdisc-security-filters:7.0.0, [11]model-evaluation:7.0.0, [12]model-integration:7.0.0, [13]vespaclient-container-plugin:7.0.0, [14]vespa-athenz:7.0.0, [15]security-utils:7.0.0, [16]defaults:7.0.0, [17]zkfacade:7.0.0, [18]zookeeper-server:7.0.0, [19]org.eclipse.jetty.alpn.api:1.1.3.v20160715, [20]org.eclipse.jetty.http2.server:9.4.40.v20210413, [21]org.eclipse.jetty.http2.common:9.4.40.v20210413, [22]org.eclipse.jetty.http2.hpack:9.4.40.v20210413, [23]org.eclipse.jetty.alpn.java.server:9.4.40.v20210413, [24]org.eclipse.jetty.alpn.server:9.4.40.v20210413, [25]org.eclipse.jetty.continuation:9.4.40.v20210413, [26]org.eclipse.jetty.http:9.4.40.v20210413, [27]org.eclipse.jetty.io:9.4.40.v20210413, [28]org.eclipse.jetty.jmx:9.4.40.v20210413, [29]org.eclipse.jetty.security:9.4.40.v20210413, [30]org.eclipse.jetty.server:9.4.40.v20210413, [31]org.eclipse.jetty.servlet:9.4.40.v20210413, [32]org.eclipse.jetty.servlets:9.4.40.v20210413, [33]org.eclipse.jetty.util:9.4.40.v20210413, [34]org.eclipse.jetty.util.ajax:9.4.40.v20210413, [35]org.apache.aries.spifly.dynamic.bundle:1.3.3, [36]org.objectweb.asm:9.1.0, [37]org.objectweb.asm.tree.analysis:9.1.0, [38]org.objectweb.asm.commons:9.1.0, [39]org.objectweb.asm.tree:9.1.0, [40]org.objectweb.asm.util:9.1.0, [41]bcpkix:1.65.0, [42]bcprov:1.65.0, [43]javax.servlet-api:3.1.0, [44]org.glassfish.hk2.external.aopalliance-repackaged:2.5.0.b32, [45]org.glassfish.hk2.api:2.5.0.b32, [46]org.glassfish.hk2.locator:2.5.0.b32, [47]org.glassfish.hk2.utils:2.5.0.b32, [48]com.fasterxml.jackson.core.jackson-annotations:2.12.1, [49]com.fasterxml.jackson.core.jackson-core:2.12.1, [50]com.fasterxml.jackson.core.jackson-databind:2.12.1, [51]com.fasterxml.jackson.datatype.jackson-datatype-jdk8:2.12.1, [52]com.fasterxml.jackson.datatype.jackson-datatype-jsr310:2.12.1, [53]com.fasterxml.jackson.jaxrs.jackson-jaxrs-base:2.12.1, [54]com.fasterxml.jackson.jaxrs.jackson-jaxrs-json-provider:2.12.1, [55]com.fasterxml.jackson.module.jackson-module-jaxb-annotations:2.12.1, [56]jakarta.activation-api:1.2.1, [57]jakarta.xml.bind-api:2.3.2, [58]javassist:3.20.0.GA, [59]javax.ws.rs-api:2.0.1, [60]org.glassfish.jersey.core.jersey-client:2.25.0, [61]org.glassfish.jersey.core.jersey-common:2.25.0, [62]org.glassfish.jersey.containers.jersey-container-servlet:2.25.0, [63]org.glassfish.jersey.containers.jersey-container-servlet-core:2.25.0, [64]org.glassfish.jersey.ext.jersey-entity-filtering:2.25.0, [65]org.glassfish.jersey.bundles.repackaged.jersey-guava:2.25.0, [66]org.glassfish.jersey.media.jersey-media-jaxb:2.25.0, [67]org.glassfish.jersey.media.jersey-media-json-jackson:2.25.0, [68]org.glassfish.jersey.media.jersey-media-multipart:2.25.0, [69]org.jvnet.mimepull:1.9.6, [70]org.glassfish.jersey.core.jersey-server:2.25.0, [71]org.glassfish.jersey.ext.jersey-proxy-client:2.25.0, [72]org.glassfish.hk2.osgi-resource-locator:1.0.1, [73]javax.validation.api:1.1.0.Final, [74]clustercontroller-apps:7.0.0, [75]clustercontroller-core:7.0.0, [76]clustercontroller-reindexer:7.0.0, [77]clustercontroller-utils:7.0.0} [2021-05-06 12:34:08] INFO : metricsproxy-container Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.service.CurrentContainer to inject into component 'DefaultHttpServer' of type 'com.yahoo.jdisc.http.server.jetty.JettyHttpServer'. [2021-05-06 12:34:09] INFO : metricsproxy-container Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.container.Container to inject into component 'com.yahoo.container.core.config.HandlersConfigurerDi$RegistriesHack'. [2021-05-06 12:34:09] INFO : metricsproxy-container Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.statistics.ContainerWatchdogMetrics to inject into component 'com.yahoo.container.jdisc.metric.MetricUpdater'. [2021-05-06 12:34:09] INFO : metricsproxy-container Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.container.http.filter.FilterChainRepository to inject into component 'com.yahoo.container.jdisc.FilterBindingsProvider in DefaultHttpServer'. [2021-05-06 12:34:09] INFO : metricsproxy-container Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.Timer to inject into component 'com.yahoo.container.jdisc.state.StateHandler'. [2021-05-06 12:34:11] INFO : metricsproxy-container Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.service.CurrentContainer to inject into component 'DefaultHttpServer' of type 'com.yahoo.jdisc.http.server.jetty.JettyHttpServer'. [2021-05-06 12:34:11] INFO : metricsproxy-container Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.container.Container to inject into component 'com.yahoo.container.core.config.HandlersConfigurerDi$RegistriesHack'. [2021-05-06 12:34:11] INFO : metricsproxy-container Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.statistics.ContainerWatchdogMetrics to inject into component 'com.yahoo.container.jdisc.metric.MetricUpdater'. [2021-05-06 12:34:11] INFO : metricsproxy-container Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.container.http.filter.FilterChainRepository to inject into component 'com.yahoo.container.jdisc.FilterBindingsProvider in DefaultHttpServer'. [2021-05-06 12:34:12] INFO : metricsproxy-container Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.Timer to inject into component 'com.yahoo.container.jdisc.state.StateHandler'. [2021-05-06 12:34:12] CONFIG : metricsproxy-container Container.com.yahoo.metrics.simple.MetricManager setting up simple metrics gathering. reportPeriodSeconds=60, pointsToKeepPerMetric=100 [2021-05-06 12:34:12] INFO : configserver Container.com.yahoo.osgi.OsgiImpl Using standalone-container [1] to lookup current bundles. [2021-05-06 12:34:12] INFO : configserver Container.com.yahoo.container.core.config.HandlersConfigurerDi Installing bundles from the latest application [2021-05-06 12:34:12] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Bundles to schedule for uninstall: [] [2021-05-06 12:34:13] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installing bundle with reference 'LocalFileDb:components/athenz-identity-provider-service.jar' [2021-05-06 12:34:15] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installing bundle with reference 'LocalFileDb:components/config-model-fat.jar' [2021-05-06 12:34:15] INFO : jdisc/configserver athenz-identity-provider-service BundleEvent INSTALLED [2021-05-06 12:34:18] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installing bundle with reference 'LocalFileDb:components/configserver.jar' [2021-05-06 12:34:18] INFO : jdisc/configserver config-model-fat BundleEvent INSTALLED [2021-05-06 12:34:21] INFO : metricsproxy-container Container.com.yahoo.jdisc.http.server.jetty.JettyHttpServer Creating janitor executor with 1 threads [2021-05-06 12:34:21] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installing bundle with reference 'LocalFileDb:components/flags.jar' [2021-05-06 12:34:21] INFO : jdisc/configserver configserver BundleEvent INSTALLED [2021-05-06 12:34:23] INFO : metricsproxy-container Container.com.yahoo.container.jdisc.state.StateMonitor Changing health status code from 'initializing' to 'up' [2021-05-06 12:34:23] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installing bundle with reference 'LocalFileDb:components/zookeeper-server.jar' [2021-05-06 12:34:23] INFO : jdisc/configserver flags BundleEvent INSTALLED [2021-05-06 12:34:23] INFO : metricsproxy-container Container.org.eclipse.jetty.server.Server jetty-9.4.40.v20210413; built: 2021-04-13T20:42:42.668Z; git: b881a572662e1943a14ae12e7e1207989f218b74; jvm 11.0.11+9-LTS [2021-05-06 12:34:23] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installing bundle with reference 'LocalFileDb:components/node-repository.jar' [2021-05-06 12:34:23] INFO : metricsproxy-container Container.org.eclipse.jetty.server.handler.ContextHandler Started o.e.j.s.ServletContextHandler@6d5f4900{19092,/,null,AVAILABLE} [2021-05-06 12:34:23] INFO : metricsproxy-container Container.org.eclipse.jetty.server.AbstractConnector Started SearchServer@3caafa67{HTTP/1.1, (http/1.1)}{0.0.0.0:19092} [2021-05-06 12:34:23] INFO : metricsproxy-container Container.org.eclipse.jetty.server.Server Started @362675ms [2021-05-06 12:34:24] INFO : metricsproxy-container Container.com.yahoo.container.jdisc.ConfiguredApplication Switching to the latest deployed set of configurations and components. Application config generation: 2 [2021-05-06 12:34:24] INFO : metricsproxy-container Container.com.yahoo.container.jdisc.ConfiguredApplication Registered name 'vespa/service/admin/metrics/vespa-2.vespa-internal.default.svc.cluster.local' at tcp/vespa-2.vespa-internal.default.svc.cluster.local:19094 with: [tcp/vespa-1.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-container-2.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-0.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-container-0.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-content-0.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-content-2.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-content-1.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-container-1.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-2.vespa-internal.default.svc.cluster.local:19099] [2021-05-06 12:34:24] INFO : metricsproxy-container Container.com.yahoo.jrt.slobrok.api.Register [RPC @ tcp/vespa-2.vespa-internal.default.svc.cluster.local:19094] registering vespa/service/admin/metrics/vespa-2.vespa-internal.default.svc.cluster.local with location broker tcp/vespa-1.vespa-internal.default.svc.cluster.local:19099 completed successfully [2021-05-06 12:34:25] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installing bundle with reference 'LocalFileDb:components/application-model.jar' [2021-05-06 12:34:25] INFO : jdisc/configserver node-repository BundleEvent INSTALLED [2021-05-06 12:34:27] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installing bundle with reference 'LocalFileDb:components/orchestrator.jar' [2021-05-06 12:34:27] INFO : jdisc/configserver application-model BundleEvent INSTALLED [2021-05-06 12:34:29] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installing bundle with reference 'LocalFileDb:components/service-monitor.jar' [2021-05-06 12:34:29] INFO : jdisc/configserver orchestrator BundleEvent INSTALLED [2021-05-06 12:34:30] INFO : container-clustercontroller Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.service.CurrentContainer to inject into component 'DefaultHttpServer' of type 'com.yahoo.jdisc.http.server.jetty.JettyHttpServer'. [2021-05-06 12:34:30] INFO : container-clustercontroller Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.container.Container to inject into component 'com.yahoo.container.core.config.HandlersConfigurerDi$RegistriesHack'. [2021-05-06 12:34:31] INFO : container-clustercontroller Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.container.http.filter.FilterChainRepository to inject into component 'com.yahoo.container.jdisc.FilterBindingsProvider in DefaultHttpServer'. [2021-05-06 12:34:31] INFO : container-clustercontroller Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.Timer to inject into component 'com.yahoo.container.jdisc.state.StateHandler'. [2021-05-06 12:34:31] INFO : container-clustercontroller Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.statistics.ContainerWatchdogMetrics to inject into component 'com.yahoo.container.jdisc.metric.MetricUpdater'. [2021-05-06 12:34:31] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installing bundle with reference 'LocalFileDb:components/configserver-flags.jar' [2021-05-06 12:34:31] INFO : jdisc/configserver service-monitor BundleEvent INSTALLED [2021-05-06 12:34:33] INFO : container-clustercontroller Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.service.CurrentContainer to inject into component 'DefaultHttpServer' of type 'com.yahoo.jdisc.http.server.jetty.JettyHttpServer'. [2021-05-06 12:34:33] INFO : jdisc/configserver configserver-flags BundleEvent INSTALLED [2021-05-06 12:34:33] INFO : container-clustercontroller Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.container.Container to inject into component 'com.yahoo.container.core.config.HandlersConfigurerDi$RegistriesHack'. [2021-05-06 12:34:34] INFO : jdisc/configserver application-model BundleEvent RESOLVED [2021-05-06 12:34:34] INFO : container-clustercontroller Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.container.http.filter.FilterChainRepository to inject into component 'com.yahoo.container.jdisc.FilterBindingsProvider in DefaultHttpServer'. [2021-05-06 12:34:34] INFO : jdisc/configserver orchestrator BundleEvent RESOLVED [2021-05-06 12:34:34] INFO : container-clustercontroller Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.Timer to inject into component 'com.yahoo.container.jdisc.state.StateHandler'. [2021-05-06 12:34:34] INFO : jdisc/configserver service-monitor BundleEvent RESOLVED [2021-05-06 12:34:34] INFO : container-clustercontroller Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.statistics.ContainerWatchdogMetrics to inject into component 'com.yahoo.container.jdisc.metric.MetricUpdater'. [2021-05-06 12:34:34] INFO : jdisc/configserver flags BundleEvent RESOLVED [2021-05-06 12:34:34] INFO : jdisc/configserver athenz-identity-provider-service BundleEvent RESOLVED [2021-05-06 12:34:34] CONFIG : container-clustercontroller Container.com.yahoo.metrics.simple.MetricManager setting up simple metrics gathering. reportPeriodSeconds=60, pointsToKeepPerMetric=100 [2021-05-06 12:34:34] INFO : jdisc/configserver node-repository BundleEvent RESOLVED [2021-05-06 12:34:34] INFO : jdisc/configserver athenz-identity-provider-service BundleEvent STARTED [2021-05-06 12:34:34] INFO : jdisc/configserver config-model-fat BundleEvent RESOLVED [2021-05-06 12:34:34] INFO : jdisc/configserver config-model-fat BundleEvent STARTED [2021-05-06 12:34:34] INFO : jdisc/configserver configserver BundleEvent RESOLVED [2021-05-06 12:34:34] INFO : jdisc/configserver configserver BundleEvent STARTED [2021-05-06 12:34:35] INFO : jdisc/configserver flags BundleEvent STARTED [2021-05-06 12:34:35] INFO : jdisc/configserver node-repository BundleEvent STARTED [2021-05-06 12:34:35] INFO : jdisc/configserver application-model BundleEvent STARTED [2021-05-06 12:34:36] INFO : jdisc/configserver orchestrator BundleEvent STARTED [2021-05-06 12:34:36] INFO : jdisc/configserver service-monitor BundleEvent STARTED [2021-05-06 12:34:36] INFO : configserver Container.com.yahoo.container.core.config.ApplicationBundleLoader Installed bundles: {[0]org.apache.felix.framework:6.0.3, [1]standalone-container:7.0.0, [2]configdefinitions:7.0.0, [3]config-provisioning:7.0.0, [4]config-bundle:7.0.0, [5]config-model-api:7.0.0, [6]config-model:7.0.0, [7]container-disc:7.0.0, [8]configgen:7.0.0, [9]container-jersey2:7.0.0, [10]container-search-and-docproc:7.0.0, [11]container-search-gui:7.0.0, [12]docprocs:7.0.0, [13]hosted-zone-api:7.0.0, [14]jdisc-security-filters:7.0.0, [15]model-evaluation:7.0.0, [16]model-integration:7.0.0, [17]vespaclient-container-plugin:7.0.0, [18]vespa-athenz:7.0.0, [19]security-utils:7.0.0, [20]defaults:7.0.0, [21]zkfacade:7.0.0, [22]zookeeper-server:7.0.0, [23]org.eclipse.jetty.alpn.api:1.1.3.v20160715, [24]org.eclipse.jetty.http2.server:9.4.40.v20210413, [25]org.eclipse.jetty.http2.common:9.4.40.v20210413, [26]org.eclipse.jetty.http2.hpack:9.4.40.v20210413, [27]org.eclipse.jetty.alpn.java.server:9.4.40.v20210413, [28]org.eclipse.jetty.alpn.server:9.4.40.v20210413, [29]org.eclipse.jetty.continuation:9.4.40.v20210413, [30]org.eclipse.jetty.http:9.4.40.v20210413, [31]org.eclipse.jetty.io:9.4.40.v20210413, [32]org.eclipse.jetty.jmx:9.4.40.v20210413, [33]org.eclipse.jetty.security:9.4.40.v20210413, [34]org.eclipse.jetty.server:9.4.40.v20210413, [35]org.eclipse.jetty.servlet:9.4.40.v20210413, [36]org.eclipse.jetty.servlets:9.4.40.v20210413, [37]org.eclipse.jetty.util:9.4.40.v20210413, [38]org.eclipse.jetty.util.ajax:9.4.40.v20210413, [39]org.apache.aries.spifly.dynamic.bundle:1.3.3, [40]org.objectweb.asm:9.1.0, [41]org.objectweb.asm.tree.analysis:9.1.0, [42]org.objectweb.asm.commons:9.1.0, [43]org.objectweb.asm.tree:9.1.0, [44]org.objectweb.asm.util:9.1.0, [45]bcpkix:1.65.0, [46]bcprov:1.65.0, [47]javax.servlet-api:3.1.0, [48]org.glassfish.hk2.external.aopalliance-repackaged:2.5.0.b32, [49]org.glassfish.hk2.api:2.5.0.b32, [50]org.glassfish.hk2.locator:2.5.0.b32, [51]org.glassfish.hk2.utils:2.5.0.b32, [52]com.fasterxml.jackson.core.jackson-annotations:2.12.1, [53]com.fasterxml.jackson.core.jackson-core:2.12.1, [54]com.fasterxml.jackson.core.jackson-databind:2.12.1, [55]com.fasterxml.jackson.datatype.jackson-datatype-jdk8:2.12.1, [56]com.fasterxml.jackson.datatype.jackson-datatype-jsr310:2.12.1, [57]com.fasterxml.jackson.jaxrs.jackson-jaxrs-base:2.12.1, [58]com.fasterxml.jackson.jaxrs.jackson-jaxrs-json-provider:2.12.1, [59]com.fasterxml.jackson.module.jackson-module-jaxb-annotations:2.12.1, [60]jakarta.activation-api:1.2.1, [61]jakarta.xml.bind-api:2.3.2, [62]javassist:3.20.0.GA, [63]javax.ws.rs-api:2.0.1, [64]org.glassfish.jersey.core.jersey-client:2.25.0, [65]org.glassfish.jersey.core.jersey-common:2.25.0, [66]org.glassfish.jersey.containers.jersey-container-servlet:2.25.0, [67]org.glassfish.jersey.containers.jersey-container-servlet-core:2.25.0, [68]org.glassfish.jersey.ext.jersey-entity-filtering:2.25.0, [69]org.glassfish.jersey.bundles.repackaged.jersey-guava:2.25.0, [70]org.glassfish.jersey.media.jersey-media-jaxb:2.25.0, [71]org.glassfish.jersey.media.jersey-media-json-jackson:2.25.0, [72]org.glassfish.jersey.media.jersey-media-multipart:2.25.0, [73]org.jvnet.mimepull:1.9.6, [74]org.glassfish.jersey.core.jersey-server:2.25.0, [75]org.glassfish.jersey.ext.jersey-proxy-client:2.25.0, [76]org.glassfish.hk2.osgi-resource-locator:1.0.1, [77]javax.validation.api:1.1.0.Final, [78]vespajlib:7.0.0, [79]athenz-identity-provider-service:7.0.0, [80]config-model-fat:7.0.0, [81]configserver:7.0.0, [82]flags:7.0.0, [83]node-repository:7.0.0, [84]application-model:7.0.0, [85]orchestrator:7.0.0, [86]service-monitor:7.0.0, [87]configserver-flags:7.0.0} [2021-05-06 12:34:36] INFO : jdisc/configserver configserver-flags BundleEvent RESOLVED [2021-05-06 12:34:36] INFO : jdisc/configserver configserver-flags BundleEvent STARTED [2021-05-06 12:34:38] INFO : container-clustercontroller Container.com.yahoo.jdisc.http.server.jetty.JettyHttpServer Creating janitor executor with 1 threads [2021-05-06 12:34:57] WARNING : container-clustercontroller stderr SLF4J: Class path contains multiple SLF4J bindings. [2021-05-06 12:34:57] WARNING : container-clustercontroller stderr SLF4J: Found binding in [bundle://9bc723bd-ec95-42e5-812f-273529bcb660_17.0:6/org/slf4j/impl/StaticLoggerBinder.class] [2021-05-06 12:34:57] WARNING : container-clustercontroller stderr SLF4J: Found binding in [bundle://9bc723bd-ec95-42e5-812f-273529bcb660_17.0:8/org/slf4j/impl/StaticLoggerBinder.class] [2021-05-06 12:34:58] WARNING : container-clustercontroller stderr SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation. [2021-05-06 12:34:58] WARNING : container-clustercontroller stderr SLF4J: Actual binding is of type [org.slf4j.impl.JDK14LoggerFactory] [2021-05-06 12:35:10] INFO : container-clustercontroller Container.com.yahoo.container.jdisc.state.StateMonitor Changing health status code from 'initializing' to 'up' [2021-05-06 12:35:13] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.FleetController Starting up cluster controller 2 for cluster music [2021-05-06 12:35:14] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Clearing master data as we lost connection on node 2 [2021-05-06 12:35:14] INFO : container-clustercontroller Container.com.yahoo.jrt.slobrok.api.Mirror successfully connected to location broker tcp/vespa-1.vespa-internal.default.svc.cluster.local:19099 (mirror initialized with 32 service names) [2021-05-06 12:35:14] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:35:14] INFO : container-clustercontroller Container.org.eclipse.jetty.server.Server jetty-9.4.40.v20210413; built: 2021-04-13T20:42:42.668Z; git: b881a572662e1943a14ae12e7e1207989f218b74; jvm 11.0.11+9-LTS [2021-05-06 12:35:15] INFO : container-clustercontroller Container.org.eclipse.jetty.server.handler.ContextHandler Started o.e.j.s.ServletContextHandler@4e67cfe1{19050,/,null,AVAILABLE} [2021-05-06 12:35:15] INFO : container-clustercontroller Container.org.eclipse.jetty.server.AbstractConnector Started SearchServer@5c887052{HTTP/1.1, (http/1.1)}{0.0.0.0:19050} [2021-05-06 12:35:15] INFO : container-clustercontroller Container.org.eclipse.jetty.server.Server Started @414657ms [2021-05-06 12:35:16] INFO : container-clustercontroller Container.com.yahoo.container.jdisc.ConfiguredApplication Switching to the latest deployed set of configurations and components. Application config generation: 2 [2021-05-06 12:35:16] INFO : container-clustercontroller Container.com.yahoo.container.jdisc.ConfiguredApplication Registered name 'vespa/service/admin/cluster-controllers/2' at tcp/vespa-2.vespa-internal.default.svc.cluster.local:19102 with: [tcp/vespa-container-1.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-content-0.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-0.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-container-2.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-content-1.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-content-2.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-container-0.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-1.vespa-internal.default.svc.cluster.local:19099, tcp/vespa-2.vespa-internal.default.svc.cluster.local:19099] [2021-05-06 12:35:16] INFO : container-clustercontroller Container.com.yahoo.jrt.slobrok.api.Register [RPC @ tcp/vespa-2.vespa-internal.default.svc.cluster.local:19102] registering vespa/service/admin/cluster-controllers/2 with location broker tcp/vespa-container-1.vespa-internal.default.svc.cluster.local:19099 completed successfully [2021-05-06 12:35:17] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Connection to zookeeper server established. Refetching master data [2021-05-06 12:35:17] WARNING : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Failed to connect to ZooKeeper at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 with session timeout 30000: KeeperErrorCode = ConnectionLoss for /vespa [2021-05-06 12:35:18] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Done setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:35:24] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:35:25] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Connection to zookeeper server established. Refetching master data [2021-05-06 12:35:26] WARNING : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Failed to connect to ZooKeeper at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 with session timeout 30000: KeeperErrorCode = ConnectionLoss for /vespa [2021-05-06 12:35:26] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Done setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:35:34] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:35:35] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Connection to zookeeper server established. Refetching master data [2021-05-06 12:35:35] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Creating ephemeral master vote node with vote to self. [2021-05-06 12:35:36] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Done setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:35:36] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got node list response from /vespa/fleetcontroller/music/indexes version 0 with 3 nodes [2021-05-06 12:35:36] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Stored new vote in ephemeral node. 2 -> 2 [2021-05-06 12:35:36] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote data from path /vespa/fleetcontroller/music/indexes/0 with code 0 and data 0 [2021-05-06 12:35:36] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote from fleetcontroller 0. Altering vote from null to 0. [2021-05-06 12:35:37] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote data from path /vespa/fleetcontroller/music/indexes/1 with code 0 and data 0 [2021-05-06 12:35:37] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote from fleetcontroller 1. Altering vote from null to 0. [2021-05-06 12:35:37] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote data from path /vespa/fleetcontroller/music/indexes/2 with code 0 and data 2 [2021-05-06 12:35:37] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote from fleetcontroller 2. Altering vote from null to 2. [2021-05-06 12:35:37] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Got new fleet data with 3 entries: {0=0, 1=0, 2=2} [2021-05-06 12:35:37] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Handling new master election, as we have received 3 entries [2021-05-06 12:35:38] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Got master election state data(0 -> 0, 1 -> 0, 2 -> 2). [2021-05-06 12:35:38] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler MASTER_ELECTION: Cluster controller 2: 0 is new master candidate, but needs to wait before it can take over [2021-05-06 12:35:38] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Altering our state to follow new fleet controller master candidate 0 [2021-05-06 12:35:38] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Stored new vote in ephemeral node. 2 -> 0 [2021-05-06 12:35:38] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Altered data in node /vespa/fleetcontroller/music/indexes/2. Requesting new vote [2021-05-06 12:35:38] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote data from path /vespa/fleetcontroller/music/indexes/2 with code 0 and data 0 [2021-05-06 12:35:39] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote from fleetcontroller 2. Altering vote from null to 0. [2021-05-06 12:35:39] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Got new fleet data with 3 entries: {0=0, 1=0, 2=0} [2021-05-06 12:35:39] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Handling new master election, as we have received 3 entries [2021-05-06 12:35:39] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Got master election state data(0 -> 0, 1 -> 0, 2 -> 0). [2021-05-06 12:35:39] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler MASTER_ELECTION: Cluster controller 2: 0 is newly elected master [2021-05-06 12:37:00] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.Timer to inject into component 'com.yahoo.vespa.service.model.ServiceMonitorImpl'. [2021-05-06 12:37:00] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.vespa.config.server.http.TesterClient to inject into component 'com.yahoo.vespa.config.server.ApplicationRepository'. [2021-05-06 12:37:07] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.Timer to inject into component 'com.yahoo.vespa.orchestrator.status.ZkStatusService'. [2021-05-06 12:37:07] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.container.Container to inject into component 'com.yahoo.container.core.config.HandlersConfigurerDi$RegistriesHack'. [2021-05-06 12:37:07] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.statistics.ContainerWatchdogMetrics to inject into component 'com.yahoo.container.jdisc.metric.MetricUpdater'. [2021-05-06 12:37:07] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.Timer to inject into component 'com.yahoo.container.jdisc.state.StateHandler'. [2021-05-06 12:37:08] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.service.CurrentContainer to inject into component 'jdisc-jetty' of type 'com.yahoo.jdisc.http.server.jetty.JettyHttpServer'. [2021-05-06 12:37:09] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.Timer to inject into component 'com.yahoo.vespa.service.model.ServiceMonitorImpl'. [2021-05-06 12:37:09] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.vespa.config.server.http.TesterClient to inject into component 'com.yahoo.vespa.config.server.ApplicationRepository'. [2021-05-06 12:37:09] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.Timer to inject into component 'com.yahoo.vespa.orchestrator.status.ZkStatusService'. [2021-05-06 12:37:09] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.container.Container to inject into component 'com.yahoo.container.core.config.HandlersConfigurerDi$RegistriesHack'. [2021-05-06 12:37:10] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.statistics.ContainerWatchdogMetrics to inject into component 'com.yahoo.container.jdisc.metric.MetricUpdater'. [2021-05-06 12:37:10] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.Timer to inject into component 'com.yahoo.container.jdisc.state.StateHandler'. [2021-05-06 12:37:10] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentGraph Trying the fallback injector to create component of class com.yahoo.jdisc.service.CurrentContainer to inject into component 'jdisc-jetty' of type 'com.yahoo.jdisc.http.server.jetty.JettyHttpServer'. [2021-05-06 12:37:14] CONFIG : configserver Container.org.glassfish.jersey.internal.ServiceFinder Running in an OSGi environment [2021-05-06 12:37:16] WARNING : configserver stderr SLF4J: Class path contains multiple SLF4J bindings. [2021-05-06 12:37:16] WARNING : configserver stderr SLF4J: Found binding in [bundle://b7edccec-3a93-4860-b730-5f8200d5572c_22.0:18/org/slf4j/impl/StaticLoggerBinder.class] [2021-05-06 12:37:16] WARNING : configserver stderr SLF4J: Found binding in [bundle://b7edccec-3a93-4860-b730-5f8200d5572c_22.0:19/org/slf4j/impl/StaticLoggerBinder.class] [2021-05-06 12:37:16] WARNING : configserver stderr SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation. [2021-05-06 12:37:16] INFO : configserver Container.com.yahoo.vespa.zookeeper.ZooKeeperRunner Starting ZooKeeper server with config file /opt/vespa/conf/zookeeper/zookeeper.cfg. Trying to establish ZooKeeper quorum (members: [vespa-0.vespa-internal.default.svc.cluster.local, vespa-1.vespa-internal.default.svc.cluster.local, vespa-2.vespa-internal.default.svc.cluster.local], attempt: 1) [2021-05-06 12:37:17] WARNING : configserver stderr SLF4J: Actual binding is of type [org.slf4j.impl.JDK14LoggerFactory] [2021-05-06 12:37:17] WARNING : configserver stderr SLF4J: Class path contains multiple SLF4J bindings. [2021-05-06 12:37:17] WARNING : configserver stderr SLF4J: Found binding in [bundle://b7edccec-3a93-4860-b730-5f8200d5572c_21.0:6/org/slf4j/impl/StaticLoggerBinder.class] [2021-05-06 12:37:17] WARNING : configserver stderr SLF4J: Found binding in [bundle://b7edccec-3a93-4860-b730-5f8200d5572c_21.0:8/org/slf4j/impl/StaticLoggerBinder.class] [2021-05-06 12:37:17] WARNING : configserver stderr SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation. [2021-05-06 12:37:17] WARNING : configserver stderr SLF4J: Actual binding is of type [org.slf4j.impl.JDK14LoggerFactory] [2021-05-06 12:37:28] CONFIG : configserver Container.com.yahoo.metrics.simple.MetricManager setting up simple metrics gathering. reportPeriodSeconds=60, pointsToKeepPerMetric=100 [2021-05-06 12:38:23] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="heartbeats_failed" value=0 [2021-05-06 12:38:23] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="register_reqs" value=0 [2021-05-06 12:38:23] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="mirror_reqs" value=0 [2021-05-06 12:38:23] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="wantadd_reqs" value=2 [2021-05-06 12:38:23] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doadd_reqs" value=1287 [2021-05-06 12:38:23] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doremove_reqs" value=2 [2021-05-06 12:38:24] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="admin_reqs" value=16 [2021-05-06 12:38:24] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="other_reqs" value=8 [2021-05-06 12:40:59] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Lost connection to zookeeper server [2021-05-06 12:40:59] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Clearing master data as we lost connection on node 2 [2021-05-06 12:41:01] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:41:14] WARNING : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Failed to connect to ZooKeeper at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 with session timeout 30000: KeeperErrorCode = ConnectionLoss for /vespa [2021-05-06 12:41:14] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Done setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:41:14] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:41:20] INFO : container-clustercontroller Container.com.yahoo.vespa.curator.Curator ZK connection state change: SUSPENDED [2021-05-06 12:41:26] INFO : container-clustercontroller Container.com.yahoo.vespa.curator.Curator ZK connection state change: RECONNECTED [2021-05-06 12:41:27] WARNING : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Failed to connect to ZooKeeper at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 with session timeout 30000: KeeperErrorCode = ConnectionLoss for /vespa [2021-05-06 12:41:27] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Done setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:41:28] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:41:46] INFO : container-clustercontroller Container.com.yahoo.vespa.curator.Curator ZK connection state change: SUSPENDED [2021-05-06 12:41:50] WARNING : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Failed to connect to ZooKeeper at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 with session timeout 30000: KeeperErrorCode = ConnectionLoss for /vespa [2021-05-06 12:41:51] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Done setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:41:51] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:41:53] INFO : container-clustercontroller Container.com.yahoo.vespa.curator.Curator ZK connection state change: RECONNECTED [2021-05-06 12:41:59] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Connection to zookeeper server established. Refetching master data [2021-05-06 12:42:00] WARNING : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Failed to connect to ZooKeeper at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 with session timeout 30000: KeeperErrorCode = ConnectionLoss for /vespa [2021-05-06 12:42:00] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Done setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:42:01] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:42:03] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Connection to zookeeper server established. Refetching master data [2021-05-06 12:42:03] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Creating ephemeral master vote node with vote to self. [2021-05-06 12:42:03] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.DatabaseHandler Fleetcontroller 2: Done setting up new ZooKeeper session at vespa-0.vespa-internal.default.svc.cluster.local:2181,vespa-1.vespa-internal.default.svc.cluster.local:2181,vespa-2.vespa-internal.default.svc.cluster.local:2181 [2021-05-06 12:42:03] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got node list response from /vespa/fleetcontroller/music/indexes version 0 with 3 nodes [2021-05-06 12:42:03] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.ZooKeeperDatabase Fleetcontroller 2: Stored new vote in ephemeral node. 2 -> 0 [2021-05-06 12:42:03] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote data from path /vespa/fleetcontroller/music/indexes/0 with code 0 and data 0 [2021-05-06 12:42:04] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote from fleetcontroller 0. Altering vote from null to 0. [2021-05-06 12:42:04] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote data from path /vespa/fleetcontroller/music/indexes/1 with code 0 and data 0 [2021-05-06 12:42:04] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote from fleetcontroller 1. Altering vote from null to 0. [2021-05-06 12:42:04] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote data from path /vespa/fleetcontroller/music/indexes/2 with code 0 and data 0 [2021-05-06 12:42:04] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.database.MasterDataGatherer Fleetcontroller 2: Got vote from fleetcontroller 2. Altering vote from null to 0. [2021-05-06 12:42:05] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Got new fleet data with 3 entries: {0=0, 1=0, 2=0} [2021-05-06 12:42:05] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Handling new master election, as we have received 3 entries [2021-05-06 12:42:05] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler Cluster controller 2: Got master election state data(0 -> 0, 1 -> 0, 2 -> 0). [2021-05-06 12:42:05] INFO : container-clustercontroller Container.com.yahoo.vespa.clustercontroller.core.MasterElectionHandler MASTER_ELECTION: Cluster controller 2: 0 is newly elected master [2021-05-06 12:43:24] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="heartbeats_failed" value=0 [2021-05-06 12:43:24] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="register_reqs" value=0 [2021-05-06 12:43:24] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="mirror_reqs" value=0 [2021-05-06 12:43:24] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="wantadd_reqs" value=2 [2021-05-06 12:43:24] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doadd_reqs" value=1782 [2021-05-06 12:43:25] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doremove_reqs" value=2 [2021-05-06 12:43:25] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="admin_reqs" value=16 [2021-05-06 12:43:25] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="other_reqs" value=8 [2021-05-06 12:44:41] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentNode Finished constructing 'com.yahoo.vespa.configserver.flags.db.FlagsDbImpl' in PT7M12.804708S [2021-05-06 12:44:44] CONFIG : configserver Container.com.yahoo.vespa.config.server.zookeeper.ConfigCurator Using jute max buffer size 52428800 [2021-05-06 12:44:47] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:44:47] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:44:47] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:45:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:45:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:45:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:45:08] INFO : configserver Container.com.yahoo.vespa.hosted.provision.node.Nodes Rewrote 0 nodes in PT0.032215S [2021-05-06 12:46:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:46:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:46:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:46:15] INFO : configserver Container.com.yahoo.container.di.componentgraph.core.ComponentNode Finished constructing 'com.yahoo.vespa.config.server.ConfigServerDB' in PT1M6.221379S [2021-05-06 12:47:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:47:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:47:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:47:33] INFO : configserver Container.com.yahoo.jrt.slobrok.api.Mirror successfully connected to location broker tcp/vespa-content-2.vespa-internal.default.svc.cluster.local:19099 (mirror initialized with 33 service names) [2021-05-06 12:47:34] INFO : configserver Container.com.yahoo.vespa.config.server.session.SessionRepository Application activated successfully: default.default (generation 2) [2021-05-06 12:47:35] INFO : configserver Container.com.yahoo.vespa.config.server.session.SessionRepository Application activated successfully: default.default (generation 2) [2021-05-06 12:47:35] INFO : configserver Container.com.yahoo.vespa.config.server.tenant.TenantRepository Adding tenant 'default', created 2021-05-05T11:20:31.361Z. Bootstrapping in PT28.082936S [2021-05-06 12:47:36] INFO : configserver Container.com.yahoo.vespa.config.server.SuperModelManager Super model is complete [2021-05-06 12:47:36] INFO : configserver Container.com.yahoo.vespa.service.duper.DuperModelManager All bootstrap tenant applications have been activated [2021-05-06 12:47:51] INFO : configserver Container.com.yahoo.jdisc.http.server.jetty.JettyHttpServer Creating janitor executor with 1 threads [2021-05-06 12:47:58] INFO : configserver Container.com.yahoo.vespa.config.server.rpc.RpcServer Rpc server will listen on port 19070 [2021-05-06 12:47:58] INFO : configserver Container.com.yahoo.container.jdisc.state.StateMonitor Changing health status code from 'initializing' to 'up' [2021-05-06 12:48:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:48:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:48:00] INFO : configserver Container.com.yahoo.vespa.service.duper.DuperModelManager All infrastructure applications have been activated [2021-05-06 12:48:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:48:00] INFO : configserver Container.org.eclipse.jetty.server.Server jetty-9.4.40.v20210413; built: 2021-04-13T20:42:42.668Z; git: b881a572662e1943a14ae12e7e1207989f218b74; jvm 11.0.11+9-LTS [2021-05-06 12:48:00] INFO : configserver Container.org.eclipse.jetty.server.handler.ContextHandler Started o.e.j.s.ServletContextHandler@88ecfad{19071,/,null,AVAILABLE} [2021-05-06 12:48:01] INFO : configserver Container.org.eclipse.jetty.server.AbstractConnector Started configserver@4dc29fd9{HTTP/1.1, (http/1.1)}{0.0.0.0:19071} [2021-05-06 12:48:01] INFO : configserver Container.org.eclipse.jetty.server.Server Started @1259382ms [2021-05-06 12:48:01] INFO : configserver Container.com.yahoo.container.jdisc.ConfiguredApplication Switching to the latest deployed set of configurations and components. Application config generation: 0 [2021-05-06 12:48:25] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="heartbeats_failed" value=0 [2021-05-06 12:48:25] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="register_reqs" value=0 [2021-05-06 12:48:25] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="mirror_reqs" value=0 [2021-05-06 12:48:25] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="wantadd_reqs" value=2 [2021-05-06 12:48:26] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doadd_reqs" value=2277 [2021-05-06 12:48:26] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doremove_reqs" value=2 [2021-05-06 12:48:26] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="admin_reqs" value=16 [2021-05-06 12:48:26] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="other_reqs" value=8 [2021-05-06 12:48:50] INFO : configserver Container.com.yahoo.vespa.config.server.maintenance.SessionsMaintainer Running SessionsMaintainer, iteration 0 [2021-05-06 12:49:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:49:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:49:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:50:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:50:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:50:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:51:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:51:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:51:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:52:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:52:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:52:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:53:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:53:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:53:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:53:26] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="heartbeats_failed" value=0 [2021-05-06 12:53:26] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="register_reqs" value=0 [2021-05-06 12:53:26] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="mirror_reqs" value=0 [2021-05-06 12:53:27] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="wantadd_reqs" value=2 [2021-05-06 12:53:27] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doadd_reqs" value=2673 [2021-05-06 12:53:27] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doremove_reqs" value=2 [2021-05-06 12:53:27] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="admin_reqs" value=16 [2021-05-06 12:53:27] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="other_reqs" value=8 [2021-05-06 12:53:50] INFO : configserver Container.com.yahoo.vespa.config.server.maintenance.SessionsMaintainer Running SessionsMaintainer, iteration 10 [2021-05-06 12:54:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:54:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:54:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:55:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:55:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:55:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:56:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:56:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:56:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:57:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:57:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:57:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:58:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:58:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:58:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 12:58:27] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="heartbeats_failed" value=0 [2021-05-06 12:58:27] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="register_reqs" value=0 [2021-05-06 12:58:27] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="mirror_reqs" value=0 [2021-05-06 12:58:28] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="wantadd_reqs" value=2 [2021-05-06 12:58:28] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doadd_reqs" value=3168 [2021-05-06 12:58:28] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="doremove_reqs" value=2 [2021-05-06 12:58:28] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="admin_reqs" value=16 [2021-05-06 12:58:28] EVENT : slobrok vespa-slobrok.rpchooks count/1 name="other_reqs" value=8 [2021-05-06 12:58:50] INFO : configserver Container.com.yahoo.vespa.config.server.maintenance.SessionsMaintainer Running SessionsMaintainer, iteration 20 [2021-05-06 12:59:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 12:59:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 12:59:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0 [2021-05-06 13:00:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=procTime value=0 [2021-05-06 13:00:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.failedRequests value=0 [2021-05-06 13:00:00] EVENT : configserver Container.com.yahoo.statistics.Counter count/1 name=configserver.requests value=0

hmusum commented 3 years ago

Based on the log even loading of bundles and components in config server takes 10 minutes and total time before it has started is over 20 minutes. No warnings or errors in the log can explain this. I would expect total startup time to be 15-30 seconds, depending on hardware.

You should probably try to run some benchmark or other tool to check that HW resources and performance are as expected. I am sorry, but with limited knowledge about what causes this I can't think of a way this can be explained by how Vespa works or is setup/configured and any way this can be fixed.

abhimech001 commented 3 years ago

Based on the log even loading of bundles and components in config server takes 10 minutes and total time before it has started is over 20 minutes. No warnings or errors in the log can explain this. I would expect total startup time to be 15-30 seconds, depending on hardware.

You should probably try to run some benchmark or other tool to check that HW resources and performance are as expected. I am sorry, but with limited knowledge about what causes this I can't think of a way this can be explained by how Vespa works or is setup/configured and any way this can be fixed.

Thank you for the reply!!! We will try to benchmark HW as per suggestion. Meanwhile, can you please suggest if it is advisible to put liveliness probe on configservers, stateless nodes and content nodes as the remedial effect would be restart of pods. Also, if yes then what http end point is to be used for liveliness probe.

bratseth commented 3 years ago

You can use the "state/v1" endpoint for that - works on the http ports of all nodes. All Vespa nodes will automatically restart services through, so it's probably not useful to take any automatic action if you don't get a 200 OK response. And if you're not careful it may disrupt e.g startup of content nodes (which may take time due to tx log replay).

kkraune commented 3 years ago

I am closing this, let us know how it goes :-)