nehajatav
commented
2 years ago Good ZK logs:
1651049424.222358 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/1 - .org.apache.zookeeper.ZooKeeper info Initiating client connection, connectString=vespa-0.vespa-internal.mynamespace.svc.cluster.local:2181 sessionTimeout=120000 watcher=org.apache.curator.ConnectionState@6cd7dc74
1651049424.442502 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/24 - .org.apache.zookeeper.server.NettyServerCnxnFactory info binding to port /0.0.0.0:2181
1651049424.477040 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/24 - .org.apache.zookeeper.server.NettyServerCnxnFactory info bound to port 2181
1651049425.419851 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/27 - .org.apache.zookeeper.ClientCnxn info Opening socket connection to server vespa-0.vespa-internal.mynamespace.svc.cluster.local/
1651049424.749450 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/0 - .org.apache.zookeeper.server.quorum.QuorumPeer info LEADING 1651049424.785559 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/0 - .org.apache.zookeeper.server.quorum.Leader info LEADING - LEADER ELECTION TOOK - 242 MS
Bad Zk logs:
1651073044.459850 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/24 - .org.apache.zookeeper.server.NettyServerCnxnFactory info configure org.apache.zookeeper.server.VespaNettyServerCnxnFactory@14a3524e secure: false on addr /0.0.0.0:2181
1651073059.514803 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/24 - .org.apache.zookeeper.server.NettyServerCnxnFactory info binding to port /0.0.0.0:2181
1651073059.585957 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/28 - .org.apache.zookeeper.ClientCnxn info Opening socket connection to server vespa-0.vespa-internal.mynamespace.svc.cluster.local/
1651073063.352647 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/0 - .org.apache.zookeeper.server.quorum.QuorumPeer info LEADING 1651073068.108425 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/0 - .org.apache.zookeeper.server.quorum.Leader info LEADING - LEADER ELECTION TOOK - 5673 MS
kkraune
Describe the bug Symptom#1: Preparing session 3 using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session/3/prepared Request failed. HTTP status code: 504 Empty responsecommand terminated with exit code 1 Symptom#2: Zookeeper logs suggest zookeeper server not running
Related issues: 1) Zookeeper warnings suggesting Zk is not up: https://github.com/vespa-engine/vespa/issues/21946 2) Since configuration is not successfully deployed, is the config proxy and config sentinel are expected to give errors like this? https://github.com/vespa-engine/vespa/issues/22291
To Reproduce This happens on certain k8s clusters consistently, but doesnt happen on others for the same application.zip and other cluster configs same. Maybe this can be reproduced if the Zk part of config server is intentionally brought down? Command: /opt/vespa/bin/vespa-deploy prepare /tmp/application.zip
Expected behavior 1) application deploy should be successful 2) zookeeper should be up
Environment (please complete the following information):
Vespa version vespa version 7.559.12 compiled with go1.16.13 on linux/amd64
Troubleshooting Information Command: /opt/vespa/bin/vespa-deploy prepare /tmp/application.zip Output: Uploading application '/tmp/application.zip' using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session Session 3 for tenant 'default' created. Preparing session 3 using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session/3/prepared Request failed. HTTP status code: 504 Empty responsecommand terminated with exit code 1
Command: /opt/vespa/bin/vespa-deploy -v -t 1800 prepare /tmp/application.zip Output: #Prepare exited without a response Uploading application '/tmp/application.zip' using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session?verbose=true {"log":[],"tenant":"default","session-id":"8","prepared":"http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session/8/prepared","content":"http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session/8/content/","message":"Session 8 for tenant 'default' created."} Session 8 for tenant 'default' created. Using config server URL http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071 read from file Preparing session 8 using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session/8/prepared?verbose=true&timeout=1800 -bash-4.4$ /opt/vespa/bin/vespa-deploy -v -t 1800 activate Using config server URL http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071 read from file Activating session 8 using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session/8/active?verbose=true&timeout=1800 Request failed. HTTP status code: 400 {"error-code":"BAD_REQUEST","message":"Session 8 is not prepared"} Session 8 is not prepared command terminated with exit code 1
bash-4.2$ curl http://localhost:19071/state/v1/health { "time" : 1651058362751, "status" : { "code" : "up" }, "metrics" : { "snapshot" : { "from" : 1.651058302018E9, "to" : 1.651058362018E9 }, "values" : [ { "name" : "requestsPerSecond", "values" : { "count" : 4, "rate" : 0.06666666666666667 } }, { "name" : "latencySeconds", "values" : { "average" : 7.5E-4, "sum" : 0.003, "count" : 4, "last" : 0.0, "max" : 22.388, "min" : 0.0, "rate" : 0.06666666666666667 } } ] } }bash-4.2$
Zookeeper logs: 1651067470.226501 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/32 - .org.apache.zookeeper.ClientCnxnSocketNetty warning future isn't success.\nexception=\nio.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: vespa-0.vespa-internal.mynamespace.svc.cluster.local/11.1.3.228:2181\nCaused by: java.net.ConnectException: Connection refused\n\tat java.base/sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)\n\tat java.base/sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777)\n\tat io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:330)\n\tat io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:707)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Thread.java:829)\n
1651050081.939925 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/40 - .org.apache.zookeeper.server.NettyServerCnxnFactory warning Zookeeper server is not running, close the connection before starting the TLS handshake 1651050083.433324 vespa-0.vespa-internal.mynamespace.svc.cluster.local 440/28 - .org.apache.zookeeper.ClientCnxn warning Session 0x0 for sever vespa-0.vespa-internal.mynamespace.svc.cluster.local/:2181, Closing socket connection. Attempting reconnect except it is a SessionExpiredException.\nexception=\nEndOfStreamException: channel for sessionid 0x0 is lost\n\tat org.apache.zookeeper.ClientCnxnSocketNetty.doTransport(ClientCnxnSocketNetty.java:285)\n\tat org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1280)\n
Configserver logs: bash-4.2$ /opt/vespa/bin/vespa-logfmt -l error,fatal,warning|grep -v configproxy|grep -v sentinel
[2022-04-27 07:43:26.535] ERROR : configserver Container.com.yahoo.protect.Process Timed out waiting for application shutdown. Please check that all your request handlers drain their request content channels. [2022-04-27 09:02:53.880] WARNING : configserver Container.com.yahoo.vespa.config.server.monitoring.ZKMetricUpdater Failure in retrieving monitoring data: (SocketTimeoutException) Read timed out
Other references interpretation https://docs.vespa.ai/en/operations/configuration-server.html#zookeeper-barrier-timeout: I believe this property doesnt have significance since we have single Zk node?
Config Access logs Only two types of logs seen {"ip":"","time":1651061644.575,"duration":22.854,"responsesize":401,"requestsize":3949418,"code":200,"method":"POST","uri":"/application/v2/tenant/default/session","version":"HTTP/1.1","agent":"vespa-deploy","host":"vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071","scheme":"http","localport":19071,"peeraddr":"","peerport":44548}
{"ip":"11.1.2.1","time":1651061680.375,"duration":0.001,"responsesize":598,"requestsize":0,"code":200,"method":"GET","uri":"/state/v1/health","version":"HTTP/1.1","agent":"kube-probe/1.21","host":":19071","scheme":"http","localport":19071,"peeraddr":"11.1.2.1","peerport":53894}
Resources already referred to: https://docs.vespa.ai/en/cloudconfig/application-packages.html#file-distribution https://docs.vespa.ai/en/operations/configuration-server.html https://github.com/vespa-engine/sample-apps/tree/master/examples/operations/multinode https://github.com/vespa-engine/sample-apps/blob/master/examples/operations/README.md#troubleshooting - already tried to set service spec.publishNotReadyAddresses: true
Prepare Troubleshooting: https://docs.vespa.ai/en/reference/application-packages-reference.html
verified Config server data: bash-4.2$ cd /opt/vespa/var/db/vespa/config_server/serverdb/tenants/default/sessions/ 2/ 3/ bash-4.2$ cat 3/.applicationMetaData {"deploy":{"user":"unknown","from":"/opt/vespa/tmp/deploy12728099286328006642","timestamp":1651062562143,"internalRedeploy":false},"application":{"id":"default:default:default","checksum":"02fe080fcc5b73193a242ad880e64330","generation":3,"previousActiveGeneration":0}}bash-4.2$
verified by deploying bad schema that step 5 is executed "Validates the xml config files using the schema, found in $VESPA_HOME/share/vespa/schema"
/opt/vespa/bin/vespa-deploy prepare /tmp/application1.zip && /opt/vespa/bin/vespa-deploy activate' Uploading application '/tmp/application1.zip' using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session Session 5 for tenant 'default' created. Preparing session 5 using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session/5/prepared Request failed. HTTP status code: 400 Invalid application package: Error loading default.default: For schema 'aycolexdocumentslexDocument', field 'downloadurl_s_attr': For expression 'attribute downloadurl_s_attr': Can not assign Array to attribute 'downloadurl_s_attr' which is Array.
command terminated with exit code 1
verified filedistribution in config node contains a jar. However, the same path on container is empty bash-4.2$ cd $VESPA_HOME/var/db/vespa/filedistribution bash-4.2$ cd a8bd49a068ad9913/vespa-application-0.5-deploy.jar ^C bash-4.2$ /opt/vespa/bin/vespa-status-filedistribution Failed to get status for request http://localhost:19071/application/v2/tenant/default/application/default/environment/prod/region/default/instance/default/filedistributionstatus?timeout=5.0: 404: {"error-code":"NOT_FOUND","message":"Unknown application id 'default.default'"} bash-4.2$
Tried to activate anyway: /opt/vespa/bin/vespa-deploy prepare /tmp/application.zip && /opt/vespa/bin/vespa-deploy activate' Uploading application '/tmp/application.zip' using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session Session 6 for tenant 'default' created. Preparing session 6 using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session/6/prepared Request failed. HTTP status code: 504 Empty responsecommand terminated with exit code 1 /opt/vespa/bin/vespa-deploy activate' Activating session 6 using http://vespa-0.vespa-internal.mynamespace.svc.cluster.local:19071/application/v2/tenant/default/session/6/active Request failed. HTTP status code: 400 Session 6 is not prepared command terminated with exit code 1
Tried connecting to Zk bash-4.2$ /opt/vespa/bin/vespa-zkcli connect localhost:2181 Connecting to localhost:2181
WATCHER::
WatchedEvent state:SyncConnected type:None path:null [main-SendThread(localhost:2181)] WARN org.apache.zookeeper.ClientCnxn - An exception was thrown while closing send thread for session 0x1d23149c0009. EndOfStreamException: channel for sessionid 0x1d23149c0009 is lost at org.apache.zookeeper.ClientCnxnSocketNetty.doTransport(ClientCnxnSocketNetty.java:285) at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1280)
WATCHER::
WatchedEvent state:Closed type:None path:null [main] ERROR org.apache.zookeeper.util.ServiceUtils - Exiting JVM with code 0 bash-4.2$
bash-4.2$ /opt/vespa/bin/vespa-zkcli ls /config/v2/tenants/default/sessions/2/userapp Connecting to localhost:2181
WATCHER::
WatchedEvent state:SyncConnected type:None path:null Node does not exist: /config/v2/tenants/default/sessions/2/userapp [main] ERROR org.apache.zookeeper.util.ServiceUtils - Exiting JVM with code 1
Additional context Config sentinal logs (i think these are expected): [2022-04-27 11:23:19.464] WARNING : config-sentinel sentinel.config.frt.frtconnection Connection to tcp/localhost:19090 failed or timed out [2022-04-27 11:23:19.608] WARNING : config-sentinel sentinel.config.frt.frtconnection FRT Connection tcp/localhost:19090 suspended until 2022-04-27 11:28:19.608 UTC [2022-04-27 11:23:28.553] WARNING : config-sentinel sentinel.config-sentinel Timeout getting config, please check your setup. Will exit and restart: Timed out while subscribing to 'cloud.config.sentinel', configid 'hosts/vespa-0.vespa-internal.mynamespace.svc.cluster.local'
Configproxy logs: [2022-04-27 05:29:06.823] WARNING : configproxy configproxy.com.yahoo.config.subscription.impl.JRTConfigRequester Request callback failed: APPLICATION_NOT_LOADED. Connection spec: tcp/vespa-0.vespa-internal.mynamespace.svc.cluster.local:19070, error message: Failed request (No application exists) from Connection { Socket[addr=/,port=40026,localport=19070] }
[2022-04-27 05:29:55.911] WARNING : configproxy stderr com.yahoo.config.subscription.ConfigInterruptedException: java.lang.InterruptedException: sleep interrupted
[2022-04-27 05:29:56.064] WARNING : configproxy stderr \tat com.yahoo.config.subscription.impl.JRTConfigSubscription.subscribe(JRTConfigSubscription.java:159)
[2022-04-27 05:29:56.265] WARNING : configproxy stderr \tat com.yahoo.config.subscription.ConfigSubscriber.subscribeAndHandleErrors(ConfigSubscriber.java:130)
[2022-04-27 05:29:56.443] WARNING : configproxy stderr \tat com.yahoo.config.subscription.impl.GenericConfigSubscriber.subscribe(GenericConfigSubscriber.java:46)
[2022-04-27 05:29:56.596] WARNING : configproxy stderr \tat com.yahoo.vespa.config.proxy.Subscriber.subscribe(Subscriber.java:36)
[2022-04-27 05:29:56.749] WARNING : configproxy stderr \tat com.yahoo.vespa.config.proxy.RpcConfigSourceClient.subscribeToConfig(RpcConfigSourceClient.java:155)
[2022-04-27 05:29:56.903] WARNING : configproxy stderr \tat com.yahoo.vespa.config.proxy.RpcConfigSourceClient.getConfig(RpcConfigSourceClient.java:142)
[2022-04-27 05:29:57.056] WARNING : configproxy stderr \tat com.yahoo.vespa.config.proxy.ProxyServer.resolveConfig(ProxyServer.java:79)
[2022-04-27 05:29:57.208] WARNING : configproxy stderr \tat com.yahoo.vespa.config.proxy.ConfigProxyRpcServer.getConfigImpl(ConfigProxyRpcServer.java:258)
[2022-04-27 05:29:57.361] WARNING : configproxy stderr \tat com.yahoo.vespa.config.proxy.ConfigProxyRpcServer.lambda$getConfigV3$1(ConfigProxyRpcServer.java:128)
[2022-04-27 05:29:57.516] WARNING : configproxy stderr \tat com.yahoo.vespa.config.proxy.ConfigProxyRpcServer.lambda$dispatchRpcRequest$13(ConfigProxyRpcServer.java:230)
[2022-04-27 05:29:57.833] WARNING : configproxy stderr \tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[2022-04-27 05:29:57.986] WARNING : configproxy stderr \tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[2022-04-27 05:29:58.139] WARNING : configproxy stderr \tat java.base/java.lang.Thread.run(Thread.java:829)
[2022-04-27 05:29:58.292] WARNING : configproxy stderr Caused by: java.lang.InterruptedException: sleep interrupted
[2022-04-27 05:29:58.445] WARNING : configproxy stderr \tat java.base/java.lang.Thread.sleep(Native Method)
[2022-04-27 05:29:58.598] WARNING : configproxy stderr \tat com.yahoo.config.subscription.impl.JRTConfigSubscription.subscribe(JRTConfigSubscription.java:157)
[2022-04-27 05:29:58.766] WARNING : configproxy stderr \t... 12 more