Description of problem: ovirt-shell gives sometimes http 500 errors. Version-Release number of selected component (if applicable): Ovirt 4.0.5 How reproducible: 100% Steps to Reproduce: 1) Run "list disk" loop with script: #!/bin/sh while [ 1 -eq 1 ]; do /usr/bin/ovirt-shell -c -E 'list disks' >/dev/null echo -n . done 2) wait for http 500 error. Will occur once in 10-15 minutes. Actual results: ........................... =========================== ERROR ======================= [500] - Internal Server Error ========================================================= =========================== ERROR ======================= command "list" is not valid or not available while not connected. ========================================================= .................................... Expected results: no errors. Additional info: content of .ovirtshellrc: [cli] autoconnect = True autopage = True [ovirt-shell] username = admin@internal renew_session = False timeout = None extended_prompt = False url = https://<engine.host>/ovirt-engine/api insecure = True kerberos = False filter = False session_timeout = None ca_file = None dont_validate_cert_chain = True key_file = None password = <password> cert_file = None
That error message is the expected reaction of the CLI when the engine fails with a 500 error. To determine what is happening we need to take a look at the /var/log/ovirt-engine/server.log and /var/log/ovirt-engine/engine.log files. Can you share them?
Last error: Di 22. Nov 20:52:50 CET 2016 ============================= ERROR ======================================= [500] - Internal Server Error ========================================================================= ============================ ERROR ======================================= command "list" is not valid or not available while not connected. ========================================================================== Di 22. Nov 20:52:50 CET 2016 server/engine logs attached
Created attachment 1222889 [details] server log
Created attachment 1222890 [details] engine log
*** Bug 1396835 has been marked as a duplicate of this bug. ***
Can you attach /var/log/httpd/ssl_access_log?
Created attachment 1222891 [details] ssl log
Unfortunately I can't reproduce this problem, and the log messages aren't really useful. However, why trying to reproduce it, using the script provided by Markus, I see that the engine is killed by the out of memory killer of the kernel. The reason is that the RSS size grows without limit. This suggests that there is a memory leak, which may cause all kinds of strange results. I am focusing on that.
Juan - should we backport for 4.0.6/4.0.7?
I am not 100% sure of the cause of the problem that Markus detected. Currently I am focusing on a possible leak of native memory, caused by the creation of multiple SSL sockets. But the problem that I can reproduce, based on that hypothesis, is a complete crash of the engine, which isn't exactly what Markus sees. However the optimization to use persistent SSL connections is important enough to consider backporting it 4.0. It is also invasive enough to consider it very carefully. I'd prefer to wait a bit to see what Martin and Ravi think. Then we can decide what to do.
By the way Markus, can you share what is the configuration of your engine? What is the amount of RAM of the machine? And the amount of RAM assigned to the engine (from /etc/ovirt-engine/engine.conf.d/10-setup-java.conf)?
engine has 12GB RAM. config is: # cat /etc/ovirt-engine/engine.conf.d/10-setup-java.conf ENGINE_HEAP_MIN="4096M" ENGINE_HEAP_MAX="4096M" @Juan: you are right your bugfix for the SSL pool does not directly fix the HTTP 500 error. As you might have noticed: The error logs give no real idea of the root cause. But what I have noticed: The error occurs more often if you are running a live disk migration during the calls. To be more precise: I run one time: /usr/bin/ovirt-shell -c -E 'action disk <diskname> move --storage_domain-name <targetdomain> multiple time (to wait until migration finishes) rdy=0 while [ $rdy -eq 0 ]; do sleep 10 echo -n "." rdy=`/usr/bin/ovirt-shell -c -E 'list disks --query "storage = '<targetdomain>' and name = '<diskname>'"' | grep <diskname> | wc -l` done
Thanks for the additional information Markus. Unfortunately I am not able to reproduce this in my environment, even with that example. I have the suspicion that the exception is generated in the authentication layer, as that is one of the parts of the application where we don't send to the log the complete exception stack traces. Can you enable the debug log for the AAA module? That, in general, is described here: https://www.ovirt.org/develop/developer-guide/engine/jmx-support In this particular case it should be a matter of running these commands: echo 'ENGINE_JMX_INTERFACE=loopback' > /etc/ovirt-engine/engine.conf.d/99-jmx.conf systemctl restart ovirt-engine export JBOSS_HOME=/usr/share/ovirt-engine-wildfy $JBOSS_HOME/bin/jboss-cli.sh --controller=localhost:8706 --connect --user=admin@internal Then, in the prompt of the 'jboss-cli' tool: /subsystem=logging/logger=org.ovirt.engine.core.aaa:add /subsystem=logging/logger=org.ovirt.engine.core.aaa:write-attribute(name=level,value=DEBUG) Once that is done the AAA module will start sending messages to the 'engine.log' file, hopefully including the complete stack trace of the exception. Once you are done collecting the results you can remove the '99-jmx.conf' file, and restart the engine, and everything will be back to the initial configuration.
Created attachment 1226483 [details] new server log
Created attachment 1226484 [details] new engine log
Next error: Mi 30. Nov 21:08:20 CET 2016 ======================================= ERROR ======================== status: 500 reason: Internal Server Error detail: java.lang.IllegalStateException ==================================================================== Mi 30. Nov 21:08:22 CET 2016 logs attached
This is a different error, but at least we have an stack trace for it. The relevant log message is the following: 2016-11-30 21:08:21,928 ERROR [org.ovirt.engine.core.bll.SearchQuery] (default task-62) [] Exception: java.lang.NullPointerException at org.ovirt.engine.core.bll.QueriesCommandBase.validatePermissions(QueriesCommandBase.java:157) [bll.jar:] That means that there is a null pointer exception here: https://github.com/oVirt/ovirt-engine/blob/ovirt-engine-4.0.5.5/backend/manager/modules/bll/src/main/java/org/ovirt/engine/core/bll/QueriesCommandBase.java#L157 The code there is like this: return getUser().isAdmin(); The only way that can generate a null pointer exception is if the "getUser()" method returns null, and that should never happen for a an authenticated request, unless the backend session is removed in the middle of the command, which shouldn't happen either. Ravi, can you take a look? Note that the logs contain the AAA debug info.
I was able to reproduce the issue, it happens when a session is created during the execution of cleanExpiredUsersSessions after the session status was retrieved from SSO.
Please backport at least the session handling fix of Ravi Nori to 4.0.x.
I agree with Markus that this should be backported to 4.0.z. Martin, can you re-target?
I agree, let's finish the fix for master and when done decide how to fix that in 4.0.z
*** Bug 1379690 has been marked as a duplicate of this bug. ***
Backport to ovirt-engine-4.0 branch is needed
4.0.6 has been the last oVirt 4.0 release, please re-target this bug.
Setting flags back to allow cloning
Verified on 4.1.0-9