Closed sneharai4 closed 5 years ago
farhan7500
commented
5 years ago If the plugin fails due to login issue and retries again and again, ultimately the array WSAPI sessions no longer respond and throw:
Service Unavailable (HTTP 503) 31 - maximum number of server connections has been reached
wdurairaj
commented
5 years ago @sneharai4 , if you are able to recreate this consistently, keep i will keep this as "high" (documenting the steps here) , otherwise, i would deprioritize to either "medium" or "low".
prablr79
commented
5 years ago @sneharai4 can you provide some steps ? else we can mark to Medium..
wdurairaj
commented
5 years ago I was able to recreate the problem of 1 session leak per backend when this setting is given with improper value
ssh_hosts_key_file = /root/.ssh/known_hosts in hpe.conf
paramiko SSH Exception is not caught and it propagates outside of hpe_3par_common in do_setup() call, and the next call which is check_for_error() is not done (which would have done the session logout),
But, when this problem happens, the backend is correctly marked in FAILED state in this command docker volume create -d hpe -o help=backends and the logs gives adequate clue about the SSHException as
_http_log_resp /usr/lib/python3.6/site-packages/python_3parclient-4.2.9-py3.6.egg/hpe3parclient/http.py:185^[[00m
2019-04-09 01:21:37.174 20 ERROR hpe3parclient.ssh [-] Error connecting via ssh: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts': FileNotFoundError: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts'^[[00m
2019-04-09 01:21:37.175 20 ERROR hpedockerplugin.volume_manager [-] ('hpeplugin_driver do_setup failed, error is: %s', "Error connecting via ssh: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts'"): paramiko.ssh_exception.SSHException: Error connecting via ssh: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts'^[[00m
2019-04-09 01:21:37.175 20 INFO hpedockerplugin.volume_manager [-] Failed to initialize 3PAR driver for array: https://192.168.67.7:8080/api/v1!Exception: HPE Docker Volume plugin not ready: ('hpeplugin_driver do_setup failed, error is: %s', "Error connecting via ssh: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts'")^[[00m
2019-04-09 01:21:37.176 20 ERROR hpedockerplugin.backend_async_initializer [-] INITIALIZING backend: 3par3 FAILED Error: HPE Docker Volume Plugin Start Plugin Service Failed: Failed to initialize 3PAR driver for array: https://192.168.67.7:8080/api/v1!Exception: HPE Docker Volume plugin not ready: ('hpeplugin_driver do_setup failed, error is: %s', "Error connecting via ssh: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts'"): hpedockerplugin.exception.HPEPluginStartPluginException: HPE Docker Volume Plugin Start Plugin Service Failed: Failed to initialize 3PAR driver for array: https://192.168.67.7:8080/api/v1!Exception: HPE Docker Volume plugin not ready: ('hpeplugin_driver do_setup failed, error is: %s', "Error connecting via ssh: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts'")^[[00m
2019-04-09 01:21:37.176 20 INFO hpedockerplugin.backend_async_initializer [-] in finally : 3par3 , {'mgr': None, 'backend_state': 'FAILED'} ^[[00m
So, in production this situation can only be hit, when
1) there is an improper value in ssh_hosts_key_file, which is indicated by a failed backend initialization and the logs indicate the failed SSH called via paramiko exception
2) The number of session leak is 1 per backend, with every restart of the plugin container, and it's cleared after a default time out of 15 mins.
Based on the above reason, we can downgrade this bug to a "medium" priority,
@sneharai4 , please let me know, if you need any other details (or) your comments
prablr79
commented
5 years ago @sneharai4 any comments ?
sneharai4
commented
5 years ago I tried re-producing the same issue, but this time I am not getting "Service Unavailable (HTTP 503) 31 - maximum number of server connections has been reached" response error.
I have one host, where hpe.conf has invalid know_hosts file path because of which the backend fails to initialize. This has created 36 sessions on 3PAR. Error in plugin-container log:
2019-04-10 08:33:50.103 20 ERROR hpedockerplugin.backend_async_initializer [-] INITIALIZING backend: DEFAULT2 FAILED Error: HPE Docker Volume Plugin Start Plugin Service Failed: Failed to initialize 3PAR driver for array: https://192.168.67.7:8080/api/v1!Exception: 'RequestException' object has no attribute 'message': hpedockerplugin.exception.HPEPluginStartPluginException: HPE Docker Volume Plugin Start Plugin Service Failed: Failed to initialize 3PAR driver for array: https://192.168.67.7:8080/api/v1!Exception: 'RequestException' object has no attribute 'message'[00m
2019-04-10 08:33:50.105 20 ERROR hpe3parclient.ssh [-] Error connecting via ssh: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts': FileNotFoundError: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts'[00m
2019-04-10 08:33:50.110 20 INFO hpedockerplugin.backend_async_initializer [-] in finally : DEFAULT2 , {'mgr': None, 'backend_state': 'FAILED'} [00m
2019-04-10 08:33:50.110 20 ERROR hpedockerplugin.volume_manager [-] ('hpeplugin_driver do_setup failed, error is: %s', "Error connecting via ssh: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts'"): paramiko.ssh_exception.SSHException: Error connecting via ssh: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts'[00m
2019-04-10 08:33:50.112 20 INFO hpedockerplugin.volume_manager [-] Failed to initialize 3PAR driver for array: https://192.168.67.7:8080/api/v1!Exception: HPE Docker Volume plugin not ready: ('hpeplugin_driver do_setup failed, error is: %s', "Error connecting via ssh: [Errno 2] No such file or directory: '/groot/.ssh/known_hosts'")[00m
2019-04-10T08:33:50+0000 [twisted.logger._global#warn] /usr/lib/python3.6/site-packages/urllib3-1.23-py3.6.egg/urllib3/connectionpool.py:857: urllib3.exceptions.InsecureRequestWarning: Unverified HTTPS request is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings
2019-04-10T08:33:50+0000 [twisted.logger._global#warn] /usr/lib/python3.6/site-packages/urllib3-1.23-py3.6.egg/urllib3/connectionpool.py:857: urllib3.exceptions.InsecureRequestWarning: Unverified HTTPS request is being made. Adding certificate verification is strongly advised. See: https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings
2019-04-10 08:33:50.114 20 INFO hpedockerplugin.volume_manager [-] Failed to initialize 3PAR driver for array: https://192.168.67.7:8080/api/v1!Exception: 'RequestException' object has no attribute 'message'[00mDetailed log: backend_init_fails_when_hpe_conf_has_incorrect_hosts_file_path.zip
invalid_host_path_hpe_conf.txt
Now, i have another host where the backend is set to OK which uses the same array which has exhausted all the sessions on 3PAR. Getting below error while creating a volume on this host:
2019-04-10T08:35:57+0000 [twisted.web.server.Request#critical]
Traceback (most recent call last):
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/server.py", line 258, in render
body = resrc.render(self)
File "/usr/lib/python3.6/site-packages/klein-17.10.0-py3.6.egg/klein/resource.py", line 210, in render
d = defer.maybeDeferred(_execute)
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/internet/defer.py", line 151, in maybeDeferred
result = f(*args, **kw)
File "/usr/lib/python3.6/site-packages/klein-17.10.0-py3.6.egg/klein/resource.py", line 204, in _execute
**kwargs)
--- <exception caught here> ---
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/internet/defer.py", line 151, in maybeDeferred
result = f(*args, **kw)
File "/usr/lib/python3.6/site-packages/klein-17.10.0-py3.6.egg/klein/app.py", line 128, in execute_endpoint
return endpoint_f(self._instance, *args, **kwargs)
File "/usr/lib/python3.6/site-packages/klein-17.10.0-py3.6.egg/klein/app.py", line 227, in _f
return _call(instance, f, request, *a, **kw)
File "/usr/lib/python3.6/site-packages/klein-17.10.0-py3.6.egg/klein/app.py", line 50, in _call
result = f(*args, **kwargs)
File "/python-hpedockerplugin/hpedockerplugin/hpe_storage_api.py", line 732, in volumedriver_get
qualified_name)
File "/python-hpedockerplugin/hpedockerplugin/backend_orchestrator.py", line 247, in get_volume_snap_details
snapname, qualified_name)
File "/python-hpedockerplugin/hpedockerplugin/backend_orchestrator.py", line 163, in _execute_request
backend, request, volname, *args, **kwargs)
File "/python-hpedockerplugin/hpedockerplugin/backend_orchestrator.py", line 152, in __execute_request
return getattr(volume_mgr, request)(volname, *args, **kwargs)
File "/python-hpedockerplugin/hpedockerplugin/volume_manager.py", line 1107, in get_volume_snap_details
vol_detail['cpg'])
File "/python-hpedockerplugin/hpedockerplugin/hpe/hpe_3par_fc.py", line 562, in get_domain
common = self._login()
File "/python-hpedockerplugin/hpedockerplugin/hpe/hpe_3par_fc.py", line 75, in _login
common.client_login()
File "/python-hpedockerplugin/hpedockerplugin/hpe/hpe_3par_common.py", line 161, in client_login
self.src_bkend_config.hpe3par_password)
File "/usr/lib/python3.6/site-packages/python_3parclient-4.2.9-py3.6.egg/hpe3parclient/client.py", line 294, in login
File "/usr/lib/python3.6/site-packages/python_3parclient-4.2.9-py3.6.egg/hpe3parclient/http.py", line 124, in authenticate
File "/usr/lib/python3.6/site-packages/python_3parclient-4.2.9-py3.6.egg/hpe3parclient/http.py", line 376, in post
File "/usr/lib/python3.6/site-packages/python_3parclient-4.2.9-py3.6.egg/hpe3parclient/http.py", line 321, in _cs_request
File "/usr/lib/python3.6/site-packages/python_3parclient-4.2.9-py3.6.egg/hpe3parclient/http.py", line 297, in _time_request
File "/usr/lib/python3.6/site-packages/python_3parclient-4.2.9-py3.6.egg/hpe3parclient/http.py", line 291, in request
hpe3parclient.exceptions.RequestException: <RequestException instance at 0x7f68606fe708 with str error:
Traceback (most recent call last):
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/python/reflect.py", line 448, in safe_str
return str(o)
File "/usr/lib/python3.6/site-packages/python_3parclient-4.2.9-py3.6.egg/hpe3parclient/exceptions.py", line 104, in __str__
formatted_string = self.message
AttributeError: 'RequestException' object has no attribute 'message'
>
2019-04-10T08:35:57+0000 [_GenericHTTPChannelProtocol,193,] Unhandled Error writing response
Traceback (most recent call last):
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/server.py", line 359, in processingFailed
util.formatFailure(reason) +
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/util.py", line 432, in formatFailure
flattenString(None, FailureElement(myFailure)).addBoth(result.append)
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/_flatten.py", line 419, in flattenString
d = flatten(request, root, io.write)
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/_flatten.py", line 401, in flatten
_writeFlattenedData(state, write, result)
--- <exception caught here> ---
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/internet/defer.py", line 654, in _runCallbacks
current.result = callback(current.result, *args, **kw)
File "/usr/lib/python3.6/site-packages/klein-17.10.0-py3.6.egg/klein/resource.py", line 256, in processing_failed
request.processingFailed(failure)
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/server.py", line 359, in processingFailed
util.formatFailure(reason) +
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/util.py", line 437, in formatFailure
result[0].raiseException()
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/python/failure.py", line 467, in raiseException
raise self.value.with_traceback(self.tb)
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/_flatten.py", line 362, in _writeFlattenedData
element = next(state)
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/_flatten.py", line 330, in _flattenTree
raise FlattenerError(e, roots, extract_tb(exc_info()[2]))
twisted.web.error.FlattenerError: Exception while flattening:
<twisted.web.util.FailureElement object at 0x7f686052bb00>
[Tag('div', children=['\n', ' ', Tag('style', attributes=OrderedDict([('type', 'text/css')]), children=['\n', ' div.error {', '\n', ' color: red;', '\n', ' font-family: Verdana, Arial, helvetica, sans-serif;', '\n', ' font-weight: bold;', '\n', ' }', '\n', '\n', ' div {', '\n', ' font-family: Verdana, Arial, helvetica, sans-serif;', '\n', ' }', '\n', '\n', ' div.stackTrace {', '\n', ' }', '\n', '\n', ' div.frame {', '\n', ' padding: 1em;', '\n', ' background: white;', '\n', ' border-bottom: thin black dashed;', '\n', ' }', '\n', '\n', ' div.frame:first-child {', '\n', ' padding: 1em;', '\n', ' background: white;', '\n', ' border-top: thin black dashed;', '\n', ' border-bottom: thin black dashed;', '\n', ' }', '\n', '\n', ' div.location {', '\n', ' }', '\n', '\n', ' span.function {', '\n', ' font-weight: bold;', '\n', ' font-family: "Courier New", courier, monospace;', '\n', ' }', '\n', '\n', ' div.snippet {', '\n', ' margin-bottom: 0.5em;', '\n', ' margin-left: 1em;', '\n', ' background: #FFFFDD;', '\n', ' }', '\n', '\n', ' div.snippetHighlightLine {', '\n', ' color: red;', '\n', ' }', '\n', '\n', ' span.code {', '\n', ' font-family: "Courier New", courier, monospace;', '\n', ' }', '\n', ' ']), '\n', '\n', ' ', Tag('div', attributes=OrderedDict([('class', 'error')]), children=['\n', ' ', Tag('span'), ': ', Tag('span'), '\n', ' ']), '\n', ' ', Tag('div', attributes=OrderedDict([('class', 'stackTrace')]), children=['\n', ' ', Tag('div', attributes=OrderedDict([('class', 'frame')]), children=['\n', ' ', Tag('div', attributes=OrderedDict([('class', 'location')]), children=['\n', ' ', Tag('span'), ':', Tag('span'), ' in', '\n', ' ', Tag('span', attributes=OrderedDict([('class', 'function')])), '\n', ' ']), '\n', ' ', Tag('div', attributes=OrderedDict([('class', 'snippet')]), children=['\n', ' ', Tag('div', children=['\n', ' ', Tag('span', attributes=OrderedDict([('class', 'lineno')])), '\n', ' ', Tag('code', attributes=OrderedDict([('class', 'code')])), '\n', ' ']), '\n', ' ']), '\n', ' ']), '\n', ' ']), '\n', ' ', Tag('div', attributes=OrderedDict([('class', 'error')]), children=['\n', ' ', Tag('span'), ': ', Tag('span'), '\n', ' ']), '\n'])]
Tag <div>
['\n', ' ', Tag('style', attributes=OrderedDict([('type', 'text/css')]), children=['\n', ' div.error {', '\n', ' color: red;', '\n', ' font-family: Verdana, Arial, helvetica, sans-serif;', '\n', ' font-weight: bold;', '\n', ' }', '\n', '\n', ' div {', '\n', ' font-family: Verdana, Arial, helvetica, sans-serif;', '\n', ' }', '\n', '\n', ' div.stackTrace {', '\n', ' }', '\n', '\n', ' div.frame {', '\n', ' padding: 1em;', '\n', ' background: white;', '\n', ' border-bottom: thin black dashed;', '\n', ' }', '\n', '\n', ' div.frame:first-child {', '\n', ' padding: 1em;', '\n', ' background: white;', '\n', ' border-top: thin black dashed;', '\n', ' border-bottom: thin black dashed;', '\n', ' }', '\n', '\n', ' div.location {', '\n', ' }', '\n', '\n', ' span.function {', '\n', ' font-weight: bold;', '\n', ' font-family: "Courier New", courier, monospace;', '\n', ' }', '\n', '\n', ' div.snippet {', '\n', ' margin-bottom: 0.5em;', '\n', ' margin-left: 1em;', '\n', ' background: #FFFFDD;', '\n', ' }', '\n', '\n', ' div.snippetHighlightLine {', '\n', ' color: red;', '\n', ' }', '\n', '\n', ' span.code {', '\n', ' font-family: "Courier New", courier, monospace;', '\n', ' }', '\n', ' ']), '\n', '\n', ' ', Tag('div', attributes=OrderedDict([('class', 'error')]), children=['\n', ' ', Tag('span'), ': ', Tag('span'), '\n', ' ']), '\n', ' ', Tag('div', attributes=OrderedDict([('class', 'stackTrace')]), children=['\n', ' ', Tag('div', attributes=OrderedDict([('class', 'frame')]), children=['\n', ' ', Tag('div', attributes=OrderedDict([('class', 'location')]), children=['\n', ' ', Tag('span'), ':', Tag('span'), ' in', '\n', ' ', Tag('span', attributes=OrderedDict([('class', 'function')])), '\n', ' ']), '\n', ' ', Tag('div', attributes=OrderedDict([('class', 'snippet')]), children=['\n', ' ', Tag('div', children=['\n', ' ', Tag('span', attributes=OrderedDict([('class', 'lineno')])), '\n', ' ', Tag('code', attributes=OrderedDict([('class', 'code')])), '\n', ' ']), '\n', ' ']), '\n', ' ']), '\n', ' ']), '\n', ' ', Tag('div', attributes=OrderedDict([('class', 'error')]), children=['\n', ' ', Tag('span'), ': ', Tag('span'), '\n', ' ']), '\n']
Tag <div>
['\n', ' ', Tag('span'), ': ', Tag('span'), '\n', ' ']
Tag <span>
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/_flatten.py", line 321, in _flattenTree
element = next(stack[-1])
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/_flatten.py", line 237, in _flattenElement
result = renderMethod(request, rootClone)
File "/usr/lib/python3.6/site-packages/Twisted-18.7.0rc1-py3.6-linux-x86_64.egg/twisted/web/util.py", line 406, in value
return tag(unicode(self.failure.value).encode('utf8'))
File "/usr/lib/python3.6/site-packages/python_3parclient-4.2.9-py3.6.egg/hpe3parclient/exceptions.py", line 104, in __str__
formatted_string = self.message
AttributeError: 'RequestException' object has no attribute 'message'Detailed log:
sneharai4
commented
5 years ago Fix is verified and working.
But need to open a new bug to log errors when the session exhausts and client is raising an exception which is not being handled correctly by 3PAR. Different error is raised for 3.3.1 and 3.2.2 array.
prablr79
commented
5 years ago @sneharai4 can you raise a new bug and close this ? else we can keep it open until we address the issue completely.. Please let me know.
sneharai4
commented
5 years ago @prablr79 Closing this issue.
Plugin error log:
Total sessions on 3PAR active at the moment when plugin gives the error:
Docker systemctl status: