CS 4.11.2+ SSVM bug when scanning templates

[bwsw]

ISSUE TYPE

• Bug Report

COMPONENT NAME

SSVM

CLOUDSTACK VERSION

4.11.2 and further, master is affected

CONFIGURATION

OS / ENVIRONMENT

N/A

SUMMARY

Several months ago I found that SSVM occasionally loses all the templates (we have a lot of them) causing massive redownloading which takes a lot of time. Today I started the investigation and found following logs on SSVM (DEBUG enabled):

2020-01-26 02:58:39,710 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) Processing command: com.cloud.agent.api.storage.ListTemplateCommand
2020-01-26 02:58:39,710 INFO  [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) Determined host 10.252.2.4 corresponds to IP 10.252.2.4
2020-01-26 02:58:39,711 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) Mounting device with nfs-style path of 10.252.2.4:/secondary
2020-01-26 02:58:39,711 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) mount nfs://10.252.2.4/secondary on /mnt/SecStorage/c082d67e-cc0c-3655-adbf-cfb545c7beec
2020-01-26 02:58:39,711 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) making available /mnt/SecStorage/c082d67e-cc0c-3655-adbf-cfb545c7beec on nfs://10.252.2.4/seconda
ry
2020-01-26 02:58:39,711 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) local folder for mount will be /mnt/SecStorage/c082d67e-cc0c-3655-adbf-cfb545c7beec
2020-01-26 02:58:39,712 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) Executing: mount 
2020-01-26 02:58:39,713 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) Executing while with timeout : 1440000
2020-01-26 02:58:39,714 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) Execution is successful.
2020-01-26 02:58:39,715 DEBUG [storage.resource.NfsSecondaryStorageResource] (agentRequest-Handler-1:null) Some device already mounted at /mnt/SecStorage/c082d67e-cc0c-3655-adbf-cfb545c7beec, no need to m
ount nfs://10.252.2.4/secondary
2020-01-26 02:58:39,718 DEBUG [storage.template.DownloadManagerImpl] (agentRequest-Handler-1:null) Executing: /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh -r /mnt/SecStorage/c082d67e
-cc0c-3655-adbf-cfb545c7beec/template/tmpl/ 
2020-01-26 02:58:39,720 DEBUG [storage.template.DownloadManagerImpl] (agentRequest-Handler-1:null) Executing while with timeout : 3600000
2020-01-26 02:58:40,170 DEBUG [storage.template.DownloadManagerImpl] (agentRequest-Handler-1:null) Exit value is 143
2020-01-26 02:58:40,175 WARN  [storage.template.DownloadManagerImpl] (agentRequest-Handler-1:null) Exception: /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh -r /mnt/SecStorage/c082d67e
-cc0c-3655-adbf-cfb545c7beec/template/tmpl/ 
java.io.IOException: Stream closed
        at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:336)
        at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
        at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
        at java.io.InputStreamReader.read(InputStreamReader.java:184)
        at java.io.BufferedReader.fill(BufferedReader.java:161)
        at java.io.BufferedReader.readLine(BufferedReader.java:324)
        at java.io.BufferedReader.readLine(BufferedReader.java:389)
        at com.cloud.utils.script.OutputInterpreter.processError(OutputInterpreter.java:37)
        at com.cloud.utils.script.Script.execute(Script.java:289)
        at org.apache.cloudstack.storage.template.DownloadManagerImpl.listTemplates(DownloadManagerImpl.java:809)
        at org.apache.cloudstack.storage.template.DownloadManagerImpl.gatherTemplateInfo(DownloadManagerImpl.java:824)
        at org.apache.cloudstack.storage.resource.NfsSecondaryStorageResource.execute(NfsSecondaryStorageResource.java:2052)
        at org.apache.cloudstack.storage.resource.NfsSecondaryStorageResource.executeRequest(NfsSecondaryStorageResource.java:306)
        at com.cloud.agent.Agent.processRequest(Agent.java:645)
        at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1083)
        at com.cloud.utils.nio.Task.call(Task.java:83)
        at com.cloud.utils.nio.Task.call(Task.java:29)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2020-01-26 02:58:40,182 INFO  [cloud.agent.Agent] (AgentShutdownThread:null) Stopping the agent: Reason = sig.kill
2020-01-26 02:58:40,187 INFO  [storage.template.DownloadManagerImpl] (agentRequest-Handler-1:null) found 0 templates[]
2020-01-26 02:58:40,188 DEBUG [cloud.agent.Agent] (AgentShutdownThread:null) Sending shutdown to management server
2020-01-26 02:58:40,188 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) Seq 190-6215811910701416453:  { Ans: , MgmtId: 179116088862604, via: 190, Ver: v1, Flags: 110, [{"com.cloud.agent.api.storage.ListTemplateAnswer":{"secUrl":"nfs://10.252.2.4/secondary","templateInfos":{},"result":true,"details":"success","wait":0}}] }
2020-01-26 02:58:40,240 DEBUG [utils.nio.NioConnection] (Agent-NioConnectionHandler-1:null) Location 1: Socket Socket[addr=/10.252.2.1,port=8250,localport=39288] closed on read.  Probably -1 returned: Connection closed with -1 on reading size.

I suppose the reason SSVM starts redownload templates is that /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh is killed by someone. I try to execute /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh -r /mnt/SecStorage/c082d67e-cc0c-3655-adbf-cfb545c7beec/template/tmpl/ manualy, it works well. Timeout of 3600000 is also fine, templates are listed in 30 seconds.

Tried to find OOM kill, no such information in dmesg:

STEPS TO REPRODUCE

Probably, large template hierarchy with significant listing time. Script delay BEFORE FIRST LINE IS RETURNED with sleep also should produce the undesired behavior.

EXPECTED RESULTS

SSVM doesn't download 'good' templates more than one time.

ACTUAL RESULTS

SSVM redownloads whole SSVM templates occasionally.

I implemented a workaround in:

/usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh

if [ -f $rootdir/template.cache ]
then
	cat $rootdir/template.cache
	exit 0
fi

and build the cache manually on the SSVM from outside (on the storage with the same script in CRON):

root@cs2-secstorage-nfs1:/etc/cron.5min# cat ssvm-workaround-fixit 
#!/bin/bash

REALDIR=/secondary/template/tmpl/
DIR=$(cat /secondary/template/tmpl/location.systemprefix)
/opt/bin/listvmtmplt.sh -r $REALDIR | sed "s#$REALDIR#$DIR#g" > /secondary/template/tmpl/template.cache.tmp
cp /secondary/template/tmpl/template.cache.tmp /secondary/template/tmpl/template.cache

So, looks like when listvmtmplt.sh is run for a long with NO RETURN STDOUT LINES it's killed...

Tracing

I found how the bug can be traced:

1st: let's look at execute which launches template lister.

It first launches process and next launches executor task which gathers output with a timeout.

2nd: let's look at TimedOutLogger which is used to get logs.

The implementation is probably wrong, as it doesn't assume that first state for reader is not ready. It assumes that it's initially ready, but ready is when the process returned something, if it didn't then it's not ready... and it terminates the process.

So, next look at Task implementation. It includes notifyAll, which interrupts the thread and causes TimedOutLogger is run in task.

Aannd.... if the script didn't return the data when the task where TimedOutLogger is launched, it's terminated by TimedOutLogger.

As for me the implementation is very unclear and error-prone and should be reimplemented. It's a critical bug for ssvm which is acting when the script is slow, which is a normal case for large secondary storages or simply when under load.

[bwsw]

Also, I suppose some kind of caching is a good way to go, it helps to decrease SSVM boot time and makes templates available ASAP.

[weizhouapache]

@bwsw I have read what you found. Do you have other logs to prove it ?
for example, StartupCommand/StartupSecondaryStorageCommand or listvmtmplt.sh in /var/log/cloud.log ? timestamp is very important for troubleshooting.

When agent in ssvm is stopped, it sent a ListTemplateAnswer with empty templates to management server, it is root cause why templates are redownloaded. We have a change move volume/template check to TimerTask to speed up ssvm startup and agent will not be stopped. It might help. I will create a PR for it.

[bwsw]

@weizhouapache As I fixed (workaround) the problem yesterday, I don't have a chance to debug it any longer. But I suppose that If you are able to add sleep 60 in front of listvmtmplt.sh before it returns anything, you will get the result I have.

[weizhouapache]

@weizhouapache As I fixed (workaround) the problem yesterday, I don't have a chance to debug it any longer. But I suppose that If you are able to add sleep 60 in front of listvmtmplt.sh before it returns anything, you will get the result I have.

@bwsw I am able to reproduce the issue

steps below

1. add "sleep 60" in /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh, for example

root@s-2-VM:~# diff -u /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh.old /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh
--- /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh.old      2020-01-27 10:54:11.561025172 +0000
+++ /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh  2020-01-27 10:32:14.665038400 +0000
@@ -48,6 +48,8 @@
  exit 2
 fi

+sleep 60
+
 for i in $(find /$rootdir -name template.properties );
 do
   d=$(dirname $i)

2. change log level in SSVM

sed -i "s/INFO/DEBUG/g" /usr/local/cloud/systemvm/conf/log4j-cloud.xml 

3. restart cloud service in SSVM, by "systemctl restart cloud", and monitor /var/log/cloud.log

4. When you see the following logs (sleep 60),restart cloud service again.

2020-01-27 10:51:20,982 DEBUG [storage.template.DownloadManagerImpl] (agentRequest-Handler-1:null) Executing: /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh -r /mnt/SecStorage/485ccf0d-3724-3575-a65e-318913593f8e/template/tmpl/

2020-01-27 10:51:20,985 DEBUG [storage.template.DownloadManagerImpl] (agentRequest-Handler-1:null) Executing while with timeout : 3600000

5. you will see the logs below in /var/log/cloud.log

2020-01-27 10:51:25,967 INFO  [cloud.agent.Agent] (AgentShutdownThread:null) Stopping the agent: Reason = sig.kill
2020-01-27 10:51:25,975 DEBUG [storage.template.DownloadManagerImpl] (agentRequest-Handler-1:null) Exit value is 143
2020-01-27 10:51:25,992 WARN  [storage.template.DownloadManagerImpl] (agentRequest-Handler-1:null) Exception: /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh -r /mnt/SecStorage/485ccf0d-3724-3575-a65e-318913593f8e/template/tmpl/
java.io.IOException: Stream closed
        at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:336)
        at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
        at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
        at java.io.InputStreamReader.read(InputStreamReader.java:184)
        at java.io.BufferedReader.fill(BufferedReader.java:161)
        at java.io.BufferedReader.readLine(BufferedReader.java:324)
        at java.io.BufferedReader.readLine(BufferedReader.java:389)
        at com.cloud.utils.script.OutputInterpreter.processError(OutputInterpreter.java:37)
        at com.cloud.utils.script.Script.execute(Script.java:289)
        at org.apache.cloudstack.storage.template.DownloadManagerImpl.listTemplates(DownloadManagerImpl.java:826)
        at org.apache.cloudstack.storage.template.DownloadManagerImpl.gatherTemplateInfo(DownloadManagerImpl.java:841)
        at org.apache.cloudstack.storage.resource.NfsSecondaryStorageResource.execute(NfsSecondaryStorageResource.java:2052)
        at org.apache.cloudstack.storage.resource.NfsSecondaryStorageResource.executeRequest(NfsSecondaryStorageResource.java:306)
        at com.cloud.agent.Agent.processRequest(Agent.java:640)
        at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053)
        at com.cloud.utils.nio.Task.call(Task.java:83)
        at com.cloud.utils.nio.Task.call(Task.java:29)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
2020-01-27 10:51:26,005 DEBUG [cloud.agent.Agent] (AgentShutdownThread:null) Sending shutdown to management server
2020-01-27 10:51:26,019 INFO  [storage.template.DownloadManagerImpl] (agentRequest-Handler-1:null) found 0 templates[]
2020-01-27 10:51:26,025 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) Seq 7-2120350999561371653:  { Ans: , MgmtId: 6694243406180, via: 7, Ver: v1, Flags: 110, [{"com.cloud.agent.api.storage.ListTemplateAnswer":{"secUrl":"nfs://10.11.118.41:/data/secondary1","templateInfos":{},"result":true,"details":"success","wait":0}}] }
2020-01-27 10:51:26,066 DEBUG [utils.nio.NioConnection] (Agent-NioConnectionHandler-1:null) Location 1: Socket Socket[addr=/10.11.118.40,port=8250,localport=52080] closed on read.  Probably -1 returned: Connection closed with -1 on reading size.
2020-01-27 10:51:26,067 DEBUG [utils.nio.NioConnection] (Agent-NioConnectionHandler-1:null) Closing socket Socket[addr=/10.11.118.40,port=8250,localport=52080]
2020-01-27 10:51:29,243 INFO  [cloud.agent.AgentShell] (main:null) Agent started

[weizhouapache]

@bwsw

my proposal is

diff --git a/services/secondary-storage/server/src/main/java/org/apache/cloudstack/storage/template/DownloadManagerImpl.java b/services/secondary-storage/server/src/main/java/org/apache/cloudstack/storage/template/DownloadManagerImpl.java
index bd5c591..14e5ae7 100644
--- a/services/secondary-storage/server/src/main/java/org/apache/cloudstack/storage/template/DownloadManagerImpl.java
+++ b/services/secondary-storage/server/src/main/java/org/apache/cloudstack/storage/template/DownloadManagerImpl.java
@@ -812,6 +812,10 @@ public class DownloadManagerImpl extends ManagerBase implements DownloadManager
         script.add("-r", rootdir);
         ZfsPathParser zpp = new ZfsPathParser(rootdir);
         script.execute(zpp);
+        if (script.getExitValue() != 0) {
+            s_logger.error("Error while executing script " + script.toString());
+            throw new CloudRuntimeException("Error while executing script " + script.toString());
+        }
         result.addAll(zpp.getPaths());
         s_logger.info("found " + zpp.getPaths().size() + " volumes" + zpp.getPaths());
         return result;
@@ -824,6 +828,10 @@ public class DownloadManagerImpl extends ManagerBase implements DownloadManager
         script.add("-r", rootdir);
         ZfsPathParser zpp = new ZfsPathParser(rootdir);
         script.execute(zpp);
+        if (script.getExitValue() != 0) {
+            s_logger.error("Error while executing script " + script.toString());
+            throw new CloudRuntimeException("Error while executing script " + script.toString());
+        }
         result.addAll(zpp.getPaths());
         s_logger.info("found " + zpp.getPaths().size() + " templates" + zpp.getPaths());
         return result;

I got the following errors in /var/log/cloud.log, which looks ok (there is not ListTemplatesAnswer sent to mgt server).

2020-01-27 13:17:35,031 DEBUG [storage.template.DownloadManagerImpl] (agentRequest-Handler-3:null) Executing: /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh -r /mnt/SecStorage/485ccf0d-3724-3575-a65e-318913593f8e/template/tmpl/
2020-01-27 13:17:35,039 DEBUG [storage.template.DownloadManagerImpl] (agentRequest-Handler-3:null) Executing while with timeout : 3600000
2020-01-27 13:17:39,293 DEBUG [storage.template.DownloadManagerImpl] (agentRequest-Handler-3:null) Exit value is 143
2020-01-27 13:17:39,355 WARN  [storage.template.DownloadManagerImpl] (agentRequest-Handler-3:null) Exception: /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh -r /mnt/SecStorage/485ccf0d-3724-3575-a65e-318913593f8e/template/tmpl/
java.io.IOException: Stream closed
        at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170)
......

2020-01-27 13:17:39,621 INFO  [cloud.agent.Agent] (AgentShutdownThread:null) Stopping the agent: Reason = sig.kill
2020-01-27 13:17:39,634 ERROR [storage.template.DownloadManagerImpl] (agentRequest-Handler-3:null) Exit value bbb is 143
2020-01-27 13:17:39,636 ERROR [storage.template.DownloadManagerImpl] (agentRequest-Handler-3:null) Error while executing script /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh -r /mnt/SecStorage/485ccf0d-3724-3575-a65e-318913593f8e/template/tmpl/
2020-01-27 13:17:39,646 WARN  [cloud.agent.Agent] (agentRequest-Handler-3:null) Caught:
com.cloud.utils.exception.CloudRuntimeException: Error while executing script /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh -r /mnt/SecStorage/485ccf0d-3724-3575-a65e-318913593f8e/template/tmpl/
        at org.apache.cloudstack.storage.template.DownloadManagerImpl.listTemplates(DownloadManagerImpl.java:835)
        at org.apache.cloudstack.storage.template.DownloadManagerImpl.gatherTemplateInfo(DownloadManagerImpl.java:851)
        at org.apache.cloudstack.storage.resource.NfsSecondaryStorageResource.execute(NfsSecondaryStorageResource.java:2052)
        at org.apache.cloudstack.storage.resource.NfsSecondaryStorageResource.executeRequest(NfsSecondaryStorageResource.java:306)
......

2020-01-27 13:17:39,649 DEBUG [cloud.agent.Agent] (AgentShutdownThread:null) Sending shutdown to management server
2020-01-27 13:17:39,668 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) Seq 7-1084804560242868231:  { Ans: , MgmtId: 6694243406180, via: 7, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: Error while executing script /usr/local/cloud/systemvm/scripts/storage/secondary/listvmtmplt.sh -r /mnt/SecStorage/485ccf0d-3724-3575-a65e-318913593f8e/template/tmpl/ \n\tat org.apache.cloudstack.storage.template.DownloadManagerImpl.listTemplates(DownloadManagerImpl.java:835)\n\tat org.apache.cloudstack.storage.template.DownloadManagerImpl.gatherTemplateInfo(DownloadManagerImpl.java:851)\n\tat org.apache.cloudstack.storage.resource.NfsSecondaryStorageResource.execute(NfsSecondaryStorageResource.java:2052)\n\tat org.apache.cloudstack.storage.resource.NfsSecondaryStorageResource.executeRequest(NfsSecondaryStorageResource.java:306)\n\tat com.cloud.agent.Agent.processRequest(Agent.java:640)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:1053)\n\tat com.cloud.utils.nio.Task.call(Task.java:83)\n\tat com.cloud.utils.nio.Task.call(Task.java:29)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\n\tat java.lang.Thread.run(Thread.java:748)\n","wait":0}}] }
2020-01-27 13:17:39,693 DEBUG [utils.nio.NioConnection] (Agent-NioConnectionHandler-1:null) Location 1: Socket Socket[addr=/10.11.118.40,port=8250,localport=60900] closed on read.  Probably -1 returned: Connection closed with -1 on reading size.
2020-01-27 13:17:39,741 DEBUG [utils.nio.NioConnection] (Agent-NioConnectionHandler-1:null) Closing socket Socket[addr=/10.11.118.40,port=8250,localport=60900]

[bwsw]

@weizhouapache so, your assumption is that script.java implementation is OK, but when restart happens, script is being killed and that's why sends wrong response to management server which causes the download for all the templates?

[weizhouapache]

@weizhouapache so, your assumption is that script.java implementation is OK, but when restart happens, script is being killed and that's why sends wrong response to management server which causes the download for all the templates?

@bwsw yes, the empty ListTemplateAnswer is the cause of template redownloading.
instead of restarting cloud service in ssvm, this issue can also be triggered by restarting management server (ssvm will reconnect to management server and send ListTemplateAnswer /ListVolumeAnswer to management server).

[bwsw]

@weizhouapache Great, many thanks. This issue started to make my life very difficult last time.