Improved logging and error handling

This commit is contained in:
Brad Warren 2015-07-23 17:09:09 -07:00
parent d2e2baa927
commit 83ad476a6d
7 changed files with 167 additions and 64 deletions

View file

@ -199,10 +199,11 @@ class DVSNI(DVChallenge):
def probe_cert(self, domain, **kwargs):
"""Probe DVSNI challenge certificate."""
host = socket.gethostbyname(domain)
logging.debug('%s resolved to %s', domain, host)
if "host" not in kwargs:
host = socket.gethostbyname(domain)
logging.debug('%s resolved to %s', domain, host)
kwargs["host"] = host
kwargs.setdefault("host", host)
kwargs.setdefault("port", self.PORT)
kwargs["name"] = self.nonce_domain
# TODO: try different methods?

View file

@ -1 +1 @@
include compatibility/testdata/rsa1024_key.pem
recursive-include tests/compatibility/testdata/ *

View file

@ -11,6 +11,8 @@ ENV APACHE_RUN_USER=daemon \
APACHE_LOG_DIR=/usr/local/apache2/logs
COPY tests/compatibility/configurators/apache/a2enmod.sh /usr/local/bin/
COPY tests/compatibility/testdata/rsa1024_key2.pem /usr/local/apache2/conf/
COPY tests/compatibility/testdata/empty_cert.pem /usr/local/apache2/conf/
# Note: this only exposes the port to other docker containers. You
# still have to bind to 443@host at runtime.

View file

@ -7,6 +7,7 @@ import mock
import zope.interface
from letsencrypt import configuration
from letsencrypt import errors as le_errors
from letsencrypt_apache import configurator
from tests.compatibility import errors
from tests.compatibility import interfaces
@ -28,14 +29,22 @@ class Proxy(configurators_common.Proxy):
super(Proxy, self).__init__(args)
self.le_config.apache_le_vhost_ext = "-le-ssl.conf"
self._patch = mock.patch('letsencrypt_apache.configurator.subprocess')
subprocess_mock = self._patch.start()
self._patches = list()
subprocess_patch = mock.patch(
"letsencrypt_apache.configurator.subprocess")
subprocess_mock = subprocess_patch.start()
subprocess_mock.check_call = self.check_call_in_docker
subprocess_mock.Popen = self.popen_in_docker
self._patches.append(subprocess_patch)
self.modules = self.version = self.test_conf = None
self._apache_configurator = None
self.server_root = self.modules = self.version = self.test_conf = None
display_patch = mock.patch(
"letsencrypt_apache.configurator.display_ops.select_vhost")
display_mock = display_patch.start()
display_mock.side_effect = le_errors.PluginError(
"Unable to determine vhost")
self._patches.append(display_mock)
self.modules = self.server_root = self.test_conf = self.version = None
self._apache_configurator = self._all_names = self._test_names = None
def __getattr__(self, name):
@ -83,16 +92,21 @@ class Proxy(configurators_common.Proxy):
def preprocess_config(self, server_root):
# pylint: disable=anomalous-backslash-in-string, no-self-use
"""Prepares the configuration for use in the Docker"""
find = subprocess.Popen(
["find", server_root, "-type", "f"],
stdout=subprocess.PIPE)
subprocess.check_call([
"xargs", "sed", "-e", "s/DocumentRoot.*/"
"DocumentRoot \/usr\/local\/apache2\/htdocs/I",
"-e", "s/SSLPassPhraseDialog.*/"
"SSLPassPhraseDialog builtin/I",
"-e", "s/TypesConfig.*/"
"TypesConfig \/usr\/local\/apache2\/conf\/mime.types/I",
"xargs", "sed", "-e", "s/DocumentRoot.*/DocumentRoot "
"\/usr\/local\/apache2\/htdocs/I",
"-e", "s/SSLPassPhraseDialog.*/SSLPassPhraseDialog builtin/I",
"-e", "s/TypesConfig.*/TypesConfig "
"\/usr\/local\/apache2\/conf\/mime.types/I",
"-e", "s/LoadModule/#LoadModule/I",
"-e", "s/SSLCertificateFile.*/SSLCertificateFile "
"\/usr\/local\/apache2\/conf\/empty_cert.pem/I",
"-e", "s/SSLCertificateKeyFile.*/SSLCertificateKeyFile "
"\/usr\/local\/apache2\/conf\/rsa1024_key2.pem/I",
"-i"], stdin=find.stdout)
def _prepare_configurator(self, server_root, config_file):
@ -111,7 +125,8 @@ class Proxy(configurators_common.Proxy):
def cleanup_from_tests(self):
"""Performs any necessary cleanup from running plugin tests"""
super(Proxy, self).cleanup_from_tests()
self._patch.stop()
for patch in self._patches:
patch.stop()
def get_all_names_answer(self):
"""Returns the set of domain names that the plugin should find"""

View file

@ -28,7 +28,6 @@ tests that the plugin supports are performed.
"""
PLUGINS = {"apache" : apache24.Proxy}
@ -36,44 +35,57 @@ logger = logging.getLogger(__name__)
def test_authenticator(plugin, config, temp_dir):
"""Tests plugin as an authenticator"""
"""Tests authenticator, returning True if the tests are successful"""
backup = _create_backup(config, temp_dir)
achalls = _create_achalls(plugin)
if not achalls:
return
# Plugin/tests support no common challenge types
return True
try:
responses = plugin.perform(achalls)
for i in xrange(len(responses)):
if not responses[i]:
logger.error(
"Plugin returned `None` or `False` response to challenge "
"for config `%s`", config)
elif isinstance(responses[i], challenges.DVSNIResponse):
if responses[i].simple_verify(achalls[i],
achalls[i].domain,
util.JWK.key.public_key(),
host="127.0.0.1",
port=plugin.https_port):
logger.info(
"Verification of DVSNI response for %s succeeded",
achalls[i].domain)
else:
logger.error(
"Verification of DVSNI response for %s in config '%s' "
"failed ", achalls[i].domain, config)
except le_errors.Error as error:
logger.info(
"Plugin raised %s during authentication with config '%s'",
error, config)
finally:
plugin.cleanup(achalls)
logger.error("Performing challenges on %s caused an error:", config)
logger.exception(error)
return False
if _dirs_are_unequal(config, backup):
logger.error("Challenge cleanup failed for config %s", config)
else:
logger.info("Challenge cleanup succeeded")
success = True
for i in xrange(len(responses)):
if not responses[i]:
logger.error(
"Plugin failed to complete %s for %s in %s",
type(achalls[i]), achalls[i].domain, config)
success = False
elif isinstance(responses[i], challenges.DVSNIResponse):
if responses[i].simple_verify(achalls[i],
achalls[i].domain,
util.JWK.key.public_key(),
host="127.0.0.1",
port=plugin.https_port):
logger.info(
"DVSNI verification for %s succeeded", achalls[i].domain)
else:
logger.error(
"DVSNI verification for %s in %s failed",
achalls[i].domain, config)
success = False
if success:
try:
plugin.cleanup(achalls)
except le_errors.Error as error:
logger.error("Challenge cleanup for %s caused an error:", config)
logger.exception(error)
success = False
if _dirs_are_unequal(config, backup):
logger.error("Challenge cleanup failed for %s", config)
return False
else:
logger.info("Challenge cleanup succeeded")
return success
def _create_achalls(plugin):
@ -100,16 +112,20 @@ def test_installer(args, plugin, config, temp_dir):
"""Tests plugin as an installer"""
backup = _create_backup(config, temp_dir)
if plugin.get_all_names().issubset(plugin.get_all_names_answer()):
names_match = plugin.get_all_names() == plugin.get_all_names_answer()
if names_match:
logger.info("get_all_names test succeeded")
else:
logger.error("get_all_names test failed for config `%s`", config)
logger.error("get_all_names test failed for config %s", config)
domains = list(plugin.get_testable_domain_names())
if test_deploy_cert(plugin, temp_dir, domains) and args.enhance:
test_enhancements(plugin, domains)
success = test_deploy_cert(plugin, temp_dir, domains)
test_rollback(plugin, config, backup)
if success and args.enhance:
success = test_enhancements(plugin, domains)
good_rollback = test_rollback(plugin, config, backup)
return names_match and success and good_rollback
def test_deploy_cert(plugin, temp_dir, domains):
@ -121,9 +137,15 @@ def test_deploy_cert(plugin, temp_dir, domains):
OpenSSL.crypto.FILETYPE_PEM, cert))
for domain in domains:
plugin.deploy_cert(domain, cert_path, util.KEY_PATH)
plugin.save("deployed")
plugin.restart()
try:
plugin.deploy_cert(domain, cert_path, util.KEY_PATH)
except le_errors.Error as error:
logger.error("Plugin failed to deploy ceritificate for %s:", domain)
logger.exception(error)
return False
if not _save_and_restart(plugin, "deployed"):
return False
verify_cert = validator.Validator().certificate
success = True
@ -139,17 +161,22 @@ def test_deploy_cert(plugin, temp_dir, domains):
def test_enhancements(plugin, domains):
"""Tests enhancements supported by the plugin"""
"""Tests supported enhancements returning True if successful"""
supported = plugin.supported_enhancements()
if "redirect" not in supported:
return
return True
for domain in domains:
plugin.enhance(domain, "redirect")
try:
plugin.enhance(domain, "redirect")
except le_errors.Error as error:
logger.error("Plugin failed to enable redirect for %s:", domain)
logger.exception(error)
return False
plugin.save("enhanced")
plugin.restart()
if not _save_and_restart(plugin, "enhanced"):
return False
verify_redirect = functools.partial(
validator.Validator().redirect, "localhost", plugin.http_port)
@ -162,15 +189,36 @@ def test_enhancements(plugin, domains):
if success:
logger.info("Enhancments test succeeded")
return success
def _save_and_restart(plugin, title=None):
"""Saves and restart the plugin, returning True if no errors occurred"""
try:
plugin.save(title)
plugin.restart()
return True
except le_errors.Error as error:
logger.error("Plugin failed to save and restart server:")
logger.exception(error)
return False
def test_rollback(plugin, config, backup):
"""Tests the rollback checkpoints function"""
plugin.rollback_checkpoints(2)
try:
plugin.rollback_checkpoints(2)
except le_errors.Error as error:
logger.error("Plugin raised an exception during rollback:")
logger.exception(error)
return False
if _dirs_are_unequal(config, backup):
logger.error("Rollback failed for config `%s`", config)
return False
else:
logger.info("Rollback succeeded")
return True
def _create_backup(config, temp_dir):
@ -249,15 +297,24 @@ def main():
try:
plugin.execute_in_docker("mkdir -p /var/log/apache2")
while plugin.has_more_configs():
success = True
try:
config = plugin.load_config()
logger.info("Loaded configuration: %s", config)
if args.auth:
test_authenticator(plugin, config, temp_dir)
if args.install:
test_installer(args, plugin, config, temp_dir)
success = test_authenticator(plugin, config, temp_dir)
if success and args.install:
success = test_installer(args, plugin, config, temp_dir)
except errors.Error as error:
logger.error("Tests on config `%s` raised: %s", config, error)
logger.error("Tests on %s raised:", config)
logger.exception(error)
success = False
if success:
logger.info("All tests on %s succeeded", config)
else:
logger.error("Tests on %s failed", config)
finally:
plugin.cleanup_from_tests()

View file

@ -0,0 +1,13 @@
-----BEGIN CERTIFICATE-----
MIICATCCAWoCCQCvMbKu4FHZ6zANBgkqhkiG9w0BAQsFADBFMQswCQYDVQQGEwJB
VTETMBEGA1UECAwKU29tZS1TdGF0ZTEhMB8GA1UECgwYSW50ZXJuZXQgV2lkZ2l0
cyBQdHkgTHRkMB4XDTE1MDcyMzIzMjc1MFoXDTE2MDcyMjIzMjc1MFowRTELMAkG
A1UEBhMCQVUxEzARBgNVBAgMClNvbWUtU3RhdGUxITAfBgNVBAoMGEludGVybmV0
IFdpZGdpdHMgUHR5IEx0ZDCBnzANBgkqhkiG9w0BAQEFAAOBjQAwgYkCgYEAws3o
y46PMLM9Gr68pbex0MhdPr7Cq4rRe9BBpnOuHFdF35Ak0aPrzFwVzLlGOir94U11
e5JYJDWJi+4FwLBRkOAfanjJ5GJ9BnEHSOdbtO+sv9uhbt+7iYOOUOngKSiJyUrM
i1THAE+B1CenxZ1KHRQCke708zkK8jVuxLeIAOMCAwEAATANBgkqhkiG9w0BAQsF
AAOBgQCC3LUP3MHk+IBmwHHZAZCX+6p4lop9SP6y6rDpWgnqEEeb9oFleHi2Rvzq
7gxl6nS5AsaSzfAygJ3zWKTwVAZyU4GOQ8QTK+nHk3+LO1X4cDbUlQfm5+YuwKDa
4LFKeovmrK6BiMLIc1J+MxUjLfCeVHYSdkZULTVXue0zif0BUA==
-----END CERTIFICATE-----

View file

@ -0,0 +1,15 @@
-----BEGIN RSA PRIVATE KEY-----
MIICXAIBAAKBgQDCzejLjo8wsz0avrylt7HQyF0+vsKritF70EGmc64cV0XfkCTR
o+vMXBXMuUY6Kv3hTXV7klgkNYmL7gXAsFGQ4B9qeMnkYn0GcQdI51u076y/26Fu
37uJg45Q6eApKInJSsyLVMcAT4HUJ6fFnUodFAKR7vTzOQryNW7Et4gA4wIDAQAB
AoGAKiAU40/krwdTg2ETslJS5W8ums7tkeLnAfs69x+02vQUbA/jpmHoL70KCcdW
5GU/mWUCrsIqxUm+gL/sBosaV/TF256qUBt2qQCZTN8MbDaNSYiiMnucOfbWdIqx
Zgls6GUoXQvPic9RUoFSlgfSjo5ezz6el5ihvRMp+wbk24ECQQD3oz4hN029DSZo
Y3+flmBn77gA0BMUvLa6hmt9b3xT5U/ToCLfbmUvpx7zV1g5era2y9qt/o3UtAbW
1zCVETgzAkEAyWHv/+RnSXp8/D4YwTVWyeWi862uNBPkuLGP/0zASdwBfBK3uBls
+VumfSCtp0kt2AXXmScg1fkHdeAVT6AkkQJBAJb2XRnCrRFiwtdAULzo3zx9Vp6o
OfmaUYrEByMgo5pBYLiSFrA+jFDQgH238YCY3mnxPA517+CLHuA5rtQw+yECQCfm
gL/pyFE1tLfhsdPuNpDwL9YqLl7hJis1+zrxQRQhRCYKK16NoxrQ/u7B38ZKaIvp
tGsC5q2elszTJkXNjBECQCVE9QCVx056vHVdPWM8z3GAeV3sJQ01HLLjebTEEz6G
jH54gk+YYPp4kjCvVUykbnB58BY2n88GQt5Jj5eLuMo=
-----END RSA PRIVATE KEY-----