From 60b6834ab04f5480e088b112c4bd1fb4ee6f4d2d Mon Sep 17 00:00:00 2001 From: Jakub Warmuz Date: Tue, 2 Jun 2015 07:51:36 +0000 Subject: [PATCH 1/6] Debug log registration errors. --- letsencrypt/cli.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/letsencrypt/cli.py b/letsencrypt/cli.py index 8fab21f44..e81f22570 100644 --- a/letsencrypt/cli.py +++ b/letsencrypt/cli.py @@ -112,7 +112,8 @@ def _init_acme(config, acc, authenticator, installer): if acc.regr is None: try: acme.register() - except errors.LetsEncryptClientError: + except errors.LetsEncryptClientError as error: + logging.debug(error) sys.exit("Unable to register an account with ACME server") return acme From 6ba133fc7c4ac977472c346619aa476390a08bad Mon Sep 17 00:00:00 2001 From: Jakub Warmuz Date: Fri, 12 Jun 2015 18:16:12 +0000 Subject: [PATCH 2/6] Debug log CLI arguments --- letsencrypt/cli.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/letsencrypt/cli.py b/letsencrypt/cli.py index e81f22570..b14417d41 100644 --- a/letsencrypt/cli.py +++ b/letsencrypt/cli.py @@ -573,11 +573,11 @@ def _paths_parser(helpful): help=config_help("server")) -def main(args=sys.argv[1:]): +def main(cli_args=sys.argv[1:]): """Command line argument parsing and main script execution.""" # note: arg parser internally handles --help (and exits afterwards) plugins = plugins_disco.PluginsRegistry.find_all() - args = create_parser(plugins, args).parse_args(args) + args = create_parser(plugins, cli_args).parse_args(cli_args) config = configuration.NamespaceConfig(args) # Displayer @@ -600,6 +600,8 @@ def main(args=sys.argv[1:]): if not args.text_mode: logger.addHandler(log.DialogHandler()) + # do not log `args`, as it contains sensitive data (e.g. revoke --key)! + logging.debug("Arguments: %r", cli_args) logging.debug("Discovered plugins: %r", plugins) if not os.geteuid() == 0: From 5b9a2f9637856a55e1dba18abeac2e722f8ef99a Mon Sep 17 00:00:00 2001 From: Jakub Warmuz Date: Mon, 22 Jun 2015 12:49:03 +0000 Subject: [PATCH 3/6] cli._setup_logging --- letsencrypt/cli.py | 29 +++++++++++++++++------------ 1 file changed, 17 insertions(+), 12 deletions(-) diff --git a/letsencrypt/cli.py b/letsencrypt/cli.py index b14417d41..2a9ec8405 100644 --- a/letsencrypt/cli.py +++ b/letsencrypt/cli.py @@ -573,6 +573,18 @@ def _paths_parser(helpful): help=config_help("server")) +def _setup_logging(args): + level = -args.verbose_count * 10 + logging.getLogger().setLevel(level) + if args.text_mode: + handler = logging.StreamHandler() + else: + handler = log.DialogHandler() + handler.setFormatter(logging.Formatter(logging.BASIC_FORMAT)) + logging.getLogger().addHandler(handler) + logging.debug("Root logging level set at %d", level) + + def main(cli_args=sys.argv[1:]): """Command line argument parsing and main script execution.""" # note: arg parser internally handles --help (and exits afterwards) @@ -587,23 +599,16 @@ def main(cli_args=sys.argv[1:]): displayer = display_util.NcursesDisplay() zope.component.provideUtility(displayer) + _setup_logging(args) + # do not log `args`, as it contains sensitive data (e.g. revoke --key)! + logging.debug("Arguments: %r", cli_args) + logging.debug("Discovered plugins: %r", plugins) + # Reporter report = reporter.Reporter() zope.component.provideUtility(report) atexit.register(report.atexit_print_messages) - # Logging - level = -args.verbose_count * 10 - logger = logging.getLogger() - logger.setLevel(level) - logging.debug("Logging level set at %d", level) - if not args.text_mode: - logger.addHandler(log.DialogHandler()) - - # do not log `args`, as it contains sensitive data (e.g. revoke --key)! - logging.debug("Arguments: %r", cli_args) - logging.debug("Discovered plugins: %r", plugins) - if not os.geteuid() == 0: logging.warning( "Root (sudo) is required to run most of letsencrypt functionality.") From eb149b9129a5e08bb2127f8bd2c17161f4a4ee3e Mon Sep 17 00:00:00 2001 From: Jakub Warmuz Date: Mon, 22 Jun 2015 12:41:08 +0000 Subject: [PATCH 4/6] CLI debug log file --- letsencrypt/cli.py | 45 ++++++++++++++++++++++++++++++----- letsencrypt/constants.py | 1 + letsencrypt/renewer.py | 3 +++ letsencrypt/tests/cli_test.py | 18 +++++++++++--- tests/boulder-integration.sh | 1 + 5 files changed, 59 insertions(+), 9 deletions(-) diff --git a/letsencrypt/cli.py b/letsencrypt/cli.py index 2a9ec8405..08d594ab1 100644 --- a/letsencrypt/cli.py +++ b/letsencrypt/cli.py @@ -3,8 +3,10 @@ import argparse import atexit import logging +import logging.handlers import os import sys +import time import configargparse import zope.component @@ -70,9 +72,6 @@ More detailed help: def _account_init(args, config): - le_util.make_or_verify_dir( - config.config_dir, constants.CONFIG_DIRS_MODE, os.geteuid()) - # Prepare for init of Client if args.email is None: return client.determine_account(config) @@ -559,6 +558,8 @@ def _paths_parser(helpful): help=config_help("config_dir")) add("paths", "--work-dir", default=flag_default("work_dir"), help=config_help("work_dir")) + add("paths", "--logs-dir", default=flag_default("logs_dir"), + help="Path to a directory where logs are stored.") add("paths", "--backup-dir", default=flag_default("backup_dir"), help=config_help("backup_dir")) add("paths", "--key-dir", default=flag_default("key_dir"), @@ -575,14 +576,39 @@ def _paths_parser(helpful): def _setup_logging(args): level = -args.verbose_count * 10 - logging.getLogger().setLevel(level) + fmt = "%(asctime)s:%(levelname)s:%(name)s:%(message)s" if args.text_mode: handler = logging.StreamHandler() + handler.setFormatter(logging.Formatter(fmt)) else: handler = log.DialogHandler() - handler.setFormatter(logging.Formatter(logging.BASIC_FORMAT)) - logging.getLogger().addHandler(handler) + # dialog box is small, display as less as possible + handler.setFormatter(logging.Formatter("%(message)s")) + handler.setLevel(level) + + # TODO: use fileConfig? + + # unconditionally log to file for debugging purposes + # TODO: change before release? + log_file_name = os.path.join(args.logs_dir, 'letsencrypt.log') + file_handler = logging.handlers.RotatingFileHandler( + log_file_name, maxBytes=2**20, backupCount=10) + # rotate on each invocation, rollover only possible when maxBytes + # is nonzero and backupCount is nonzero, so we set maxBytes as big + # as possible not to overrun in single CLI invocation (1MB). + file_handler.doRollover() # TODO: creates empty letsencrypt.log.1 file + file_handler.setLevel(logging.DEBUG) + file_handler_formatter = logging.Formatter(fmt=fmt) + file_handler_formatter.converter = time.gmtime # don't use localtime + file_handler.setFormatter(file_handler_formatter) + + root_logger = logging.getLogger() + root_logger.setLevel(logging.DEBUG) # send all records to handlers + root_logger.addHandler(handler) + root_logger.addHandler(file_handler) + logging.debug("Root logging level set at %d", level) + logging.info("Saving debug log to %s", log_file_name) def main(cli_args=sys.argv[1:]): @@ -599,6 +625,13 @@ def main(cli_args=sys.argv[1:]): displayer = display_util.NcursesDisplay() zope.component.provideUtility(displayer) + for directory in config.config_dir, config.work_dir: + le_util.make_or_verify_dir( + directory, constants.CONFIG_DIRS_MODE, os.geteuid()) + # TODO: logs might contain sensitive data such as contents of the + # private key! #525 + le_util.make_or_verify_dir(args.logs_dir, 0o700, os.geteuid()) + _setup_logging(args) # do not log `args`, as it contains sensitive data (e.g. revoke --key)! logging.debug("Arguments: %r", cli_args) diff --git a/letsencrypt/constants.py b/letsencrypt/constants.py index 81ec4a90b..46d9aa044 100644 --- a/letsencrypt/constants.py +++ b/letsencrypt/constants.py @@ -15,6 +15,7 @@ CLI_DEFAULTS = dict( rollback_checkpoints=0, config_dir="/etc/letsencrypt", work_dir="/var/lib/letsencrypt", + logs_dir="/var/log/letsencrypt", no_verify_ssl=False, dvsni_port=challenges.DVSNI.PORT, cert_path="./cert.pem", diff --git a/letsencrypt/renewer.py b/letsencrypt/renewer.py index d2c0b8e7d..47fbefcf8 100644 --- a/letsencrypt/renewer.py +++ b/letsencrypt/renewer.py @@ -106,6 +106,9 @@ def _paths_parser(parser): help=cli.config_help("config_dir")) add("--work-dir", default=cli.flag_default("work_dir"), help=cli.config_help("work_dir")) + add("--logs-dir", default=cli.flag_default("logs_dir"), + help="Path to a directory where logs are stored.") + return parser diff --git a/letsencrypt/tests/cli_test.py b/letsencrypt/tests/cli_test.py index 9bb8084d5..1e8e84f6d 100644 --- a/letsencrypt/tests/cli_test.py +++ b/letsencrypt/tests/cli_test.py @@ -1,5 +1,8 @@ """Tests for letsencrypt.cli.""" import itertools +import os +import shutil +import tempfile import unittest import mock @@ -8,10 +11,19 @@ import mock class CLITest(unittest.TestCase): """Tests for different commands.""" - @classmethod - def _call(cls, args): + def setUp(self): + self.tmp_dir = tempfile.mkdtemp() + self.config_dir = os.path.join(self.tmp_dir, 'config') + self.work_dir = os.path.join(self.tmp_dir, 'work') + self.logs_dir = os.path.join(self.tmp_dir, 'logs') + + def tearDown(self): + shutil.rmtree(self.tmp_dir) + + def _call(self, args): from letsencrypt import cli - args = ['--text'] + args + args = ['--text', '--config-dir', self.config_dir, + '--work-dir', self.work_dir, '--logs-dir', self.logs_dir] + args with mock.patch('letsencrypt.cli.sys.stdout') as stdout: with mock.patch('letsencrypt.cli.sys.stderr') as stderr: with mock.patch('letsencrypt.cli.client') as client: diff --git a/tests/boulder-integration.sh b/tests/boulder-integration.sh index c3cc49c70..32255039b 100755 --- a/tests/boulder-integration.sh +++ b/tests/boulder-integration.sh @@ -6,6 +6,7 @@ root="$(mktemp -d)" echo "\nRoot integration tests directory: $root" store_flags="--config-dir $root/conf --work-dir $root/work" +store_flags="$store_flags --logs-dir $root/logs" common() { # first three flags required, rest is handy defaults From 865d9074e4bfbb4540f7f35ed6726e8986d9da5a Mon Sep 17 00:00:00 2001 From: Jakub Warmuz Date: Mon, 22 Jun 2015 12:44:55 +0000 Subject: [PATCH 5/6] log.DialogHandler: print formatted record, not just message. Fixes bug, where DialogHandler would display only %(message) part of the record, instead of the entire formatted record string. --- letsencrypt/log.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/letsencrypt/log.py b/letsencrypt/log.py index a31bad8e3..e800d37c9 100644 --- a/letsencrypt/log.py +++ b/letsencrypt/log.py @@ -37,7 +37,7 @@ class DialogHandler(logging.Handler): # pylint: disable=too-few-public-methods lines. """ - for line in record.getMessage().splitlines(): + for line in self.format(record).splitlines(): # check for lines that would wrap cur_out = line while len(cur_out) > self.width: From 4ce4e2f93010fa1f0fcfb513698b01f9bb7b44b4 Mon Sep 17 00:00:00 2001 From: Jakub Warmuz Date: Thu, 11 Jun 2015 13:45:41 +0000 Subject: [PATCH 6/6] logger = logging.getLogger(__name__) --- .pylintrc | 4 +- acme/client.py | 24 ++++++----- acme/jose/json_util.py | 5 ++- acme/other.py | 5 ++- letsencrypt/account.py | 5 ++- letsencrypt/augeas_configurator.py | 14 ++++--- letsencrypt/auth_handler.py | 17 ++++---- letsencrypt/cli.py | 23 +++++----- letsencrypt/client.py | 25 ++++++----- letsencrypt/crypto_util.py | 11 +++-- letsencrypt/display/enhancements.py | 4 +- letsencrypt/display/ops.py | 10 +++-- letsencrypt/plugins/disco.py | 13 +++--- letsencrypt/plugins/manual.py | 11 +++-- letsencrypt/reporter.py | 5 ++- letsencrypt/reverter.py | 45 ++++++++++---------- letsencrypt/revoker.py | 11 +++-- letsencrypt/tests/reverter_test.py | 14 +++---- letsencrypt/tests/revoker_test.py | 4 +- letsencrypt_apache/configurator.py | 65 +++++++++++++++-------------- letsencrypt_apache/dvsni.py | 5 ++- letsencrypt_apache/parser.py | 2 +- letsencrypt_nginx/configurator.py | 19 +++++---- letsencrypt_nginx/dvsni.py | 5 ++- letsencrypt_nginx/parser.py | 9 ++-- 25 files changed, 207 insertions(+), 148 deletions(-) diff --git a/.pylintrc b/.pylintrc index 5302133ad..88cb563fa 100644 --- a/.pylintrc +++ b/.pylintrc @@ -82,7 +82,7 @@ required-attributes= bad-functions=map,filter,apply,input,file # Good variable names which should always be accepted, separated by a comma -good-names=f,i,j,k,ex,Run,_,fd +good-names=f,i,j,k,ex,Run,_,fd,logger # Bad variable names which should always be refused, separated by a comma bad-names=foo,bar,baz,toto,tutu,tata @@ -173,7 +173,7 @@ notes=FIXME,XXX,TODO # Logging modules to check that the string format arguments are in logging # function parameter format -logging-modules=logging +logging-modules=logging,logger [VARIABLES] diff --git a/acme/client.py b/acme/client.py index 6bb0f5412..d1bf84a21 100644 --- a/acme/client.py +++ b/acme/client.py @@ -15,6 +15,8 @@ from acme import jws from acme import messages +logger = logging.getLogger(__name__) + # https://urllib3.readthedocs.org/en/latest/security.html#insecureplatformwarning requests.packages.urllib3.contrib.pyopenssl.inject_into_urllib3() @@ -54,7 +56,7 @@ class Client(object): # pylint: disable=too-many-instance-attributes """ dumps = obj.json_dumps() - logging.debug('Serialized JSON: %s', dumps) + logger.debug('Serialized JSON: %s', dumps) return jws.JWS.sign( payload=dumps, key=self.key, alg=self.alg, nonce=nonce).json_dumps() @@ -77,8 +79,8 @@ class Client(object): # pylint: disable=too-many-instance-attributes :raises .ClientError: In case of other networking errors. """ - logging.debug('Received response %s (headers: %s): %r', - response, response.headers, response.content) + logger.debug('Received response %s (headers: %s): %r', + response, response.headers, response.content) response_ct = response.headers.get('Content-Type') try: @@ -91,7 +93,7 @@ class Client(object): # pylint: disable=too-many-instance-attributes if not response.ok: if jobj is not None: if response_ct != cls.JSON_ERROR_CONTENT_TYPE: - logging.debug( + logger.debug( 'Ignoring wrong Content-Type (%r) for JSON Error', response_ct) try: @@ -104,7 +106,7 @@ class Client(object): # pylint: disable=too-many-instance-attributes raise errors.ClientError(response) else: if jobj is not None and response_ct != cls.JSON_CONTENT_TYPE: - logging.debug( + logger.debug( 'Ignoring wrong Content-Type (%r) for JSON decodable ' 'response', response_ct) @@ -121,7 +123,7 @@ class Client(object): # pylint: disable=too-many-instance-attributes :rtype: `requests.Response` """ - logging.debug('Sending GET request to %s', uri) + logger.debug('Sending GET request to %s', uri) kwargs.setdefault('verify', self.verify_ssl) try: response = requests.get(uri, **kwargs) @@ -135,7 +137,7 @@ class Client(object): # pylint: disable=too-many-instance-attributes nonce = response.headers[self.REPLAY_NONCE_HEADER] error = jws.Header.validate_nonce(nonce) if error is None: - logging.debug('Storing nonce: %r', nonce) + logger.debug('Storing nonce: %r', nonce) self._nonces.add(nonce) else: raise errors.ClientError('Invalid nonce ({0}): {1}'.format( @@ -147,7 +149,7 @@ class Client(object): # pylint: disable=too-many-instance-attributes def _get_nonce(self, uri): if not self._nonces: - logging.debug('Requesting fresh nonce by sending HEAD to %s', uri) + logger.debug('Requesting fresh nonce by sending HEAD to %s', uri) self._add_nonce(requests.head(uri)) return self._nonces.pop() @@ -164,7 +166,7 @@ class Client(object): # pylint: disable=too-many-instance-attributes """ data = self._wrap_in_jws(obj, self._get_nonce(uri)) - logging.debug('Sending POST data to %s: %s', uri, data) + logger.debug('Sending POST data to %s: %s', uri, data) kwargs.setdefault('verify', self.verify_ssl) try: response = requests.post(uri, data=data, **kwargs) @@ -394,7 +396,7 @@ class Client(object): # pylint: disable=too-many-instance-attributes """ assert authzrs, "Authorizations list is empty" - logging.debug("Requesting issuance...") + logger.debug("Requesting issuance...") # TODO: assert len(authzrs) == number of SANs req = messages.CertificateRequest( @@ -458,7 +460,7 @@ class Client(object): # pylint: disable=too-many-instance-attributes now = datetime.datetime.now() if when > now: seconds = (when - now).seconds - logging.debug('Sleeping for %d seconds', seconds) + logger.debug('Sleeping for %d seconds', seconds) time.sleep(seconds) # Note that we poll with the latest updated Authorization diff --git a/acme/jose/json_util.py b/acme/jose/json_util.py index f38ebc62f..70ac5a549 100644 --- a/acme/jose/json_util.py +++ b/acme/jose/json_util.py @@ -18,6 +18,9 @@ from acme.jose import interfaces from acme.jose import util +logger = logging.getLogger(__name__) + + class Field(object): """JSON object field. @@ -233,7 +236,7 @@ class JSONObjectWithFields(util.ImmutableMap, interfaces.JSONDeSerializable): slot, value, error)) if omitted: # pylint: disable=star-args - logging.debug('Omitted empty fields: %s', ', '.join( + logger.debug('Omitted empty fields: %s', ', '.join( '{0!s}={1!r}'.format(*field) for field in omitted)) return jobj diff --git a/acme/other.py b/acme/other.py index d7eb49156..20accdcb4 100644 --- a/acme/other.py +++ b/acme/other.py @@ -8,6 +8,9 @@ import Crypto.PublicKey.RSA from acme import jose +logger = logging.getLogger(__name__) + + class Signature(jose.JSONObjectWithFields): """ACME signature. @@ -54,7 +57,7 @@ class Signature(jose.JSONObjectWithFields): msg_with_nonce = nonce + msg sig = alg.sign(key, nonce + msg) - logging.debug('%s signed as %s', msg_with_nonce, sig) + logger.debug('%s signed as %s', msg_with_nonce, sig) return cls(alg=alg, sig=sig, nonce=nonce, jwk=alg.kty(key=key.publickey())) diff --git a/letsencrypt/account.py b/letsencrypt/account.py index f651bfdb2..3304f6452 100644 --- a/letsencrypt/account.py +++ b/letsencrypt/account.py @@ -16,6 +16,9 @@ from letsencrypt import le_util from letsencrypt.display import util as display_util +logger = logging.getLogger(__name__) + + class Account(object): """ACME protocol registration. @@ -226,5 +229,5 @@ class Account(object): if cls.EMAIL_REGEX.match(email): return not email.startswith(".") and ".." not in email else: - logging.warn("Invalid email address: %s.", email) + logger.warn("Invalid email address: %s.", email) return False diff --git a/letsencrypt/augeas_configurator.py b/letsencrypt/augeas_configurator.py index a375b2e17..ffe363035 100644 --- a/letsencrypt/augeas_configurator.py +++ b/letsencrypt/augeas_configurator.py @@ -6,6 +6,8 @@ import augeas from letsencrypt import reverter from letsencrypt.plugins import common +logger = logging.getLogger(__name__) + class AugeasConfigurator(common.Plugin): """Base Augeas Configurator class. @@ -52,7 +54,7 @@ class AugeasConfigurator(common.Plugin): lens_path = self.aug.get(path + "/lens") # As aug.get may return null if lens_path and lens in lens_path: - logging.error( + logger.error( "There has been an error in parsing the file (%s): %s", # Strip off /augeas/files and /error path[13:len(path) - 6], self.aug.get(path + "/message")) @@ -121,11 +123,11 @@ class AugeasConfigurator(common.Plugin): """ # Check for the root of save problems new_errs = self.aug.match("/augeas//error") - # logging.error("During Save - %s", mod_conf) - logging.error("Unable to save files: %s. Attempted Save Notes: %s", - ", ".join(err[13:len(err) - 6] for err in new_errs - # Only new errors caused by recent save - if err not in ex_errs), self.save_notes) + # logger.error("During Save - %s", mod_conf) + logger.error("Unable to save files: %s. Attempted Save Notes: %s", + ", ".join(err[13:len(err) - 6] for err in new_errs + # Only new errors caused by recent save + if err not in ex_errs), self.save_notes) # Wrapper functions for Reverter class def recovery_routine(self): diff --git a/letsencrypt/auth_handler.py b/letsencrypt/auth_handler.py index 43f7b9fd2..2929166c2 100644 --- a/letsencrypt/auth_handler.py +++ b/letsencrypt/auth_handler.py @@ -14,6 +14,9 @@ from letsencrypt import errors from letsencrypt import interfaces +logger = logging.getLogger(__name__) + + class AuthHandler(object): """ACME Authorization Handler for a client. @@ -76,7 +79,7 @@ class AuthHandler(object): # While there are still challenges remaining... while self.dv_c or self.cont_c: cont_resp, dv_resp = self._solve_challenges() - logging.info("Waiting for verification...") + logger.info("Waiting for verification...") # Send all Responses - this modifies dv_c and cont_c self._respond(cont_resp, dv_resp, best_effort) @@ -89,7 +92,7 @@ class AuthHandler(object): def _choose_challenges(self, domains): """Retrieve necessary challenges to satisfy server.""" - logging.info("Performing the following challenges:") + logger.info("Performing the following challenges:") for dom in domains: path = gen_challenge_path( self.authzr[dom].body.challenges, @@ -112,8 +115,8 @@ class AuthHandler(object): dv_resp = self.dv_auth.perform(self.dv_c) # This will catch both specific types of errors. except errors.AuthorizationError: - logging.critical("Failure in setting up challenges.") - logging.info("Attempting to clean up outstanding challenges...") + logger.critical("Failure in setting up challenges.") + logger.info("Attempting to clean up outstanding challenges...") self._cleanup_challenges() raise @@ -261,7 +264,7 @@ class AuthHandler(object): If achall_list is not provided, cleanup all achallenges. """ - logging.info("Cleaning up challenges") + logger.info("Cleaning up challenges") if achall_list is None: dv_c = self.dv_c @@ -342,7 +345,7 @@ def challb_to_achall(challb, key, domain): """ chall = challb.chall - logging.info("%s challenge for %s", chall.typ, domain) + logger.info("%s challenge for %s", chall.typ, domain) if isinstance(chall, challenges.DVSNI): return achallenges.DVSNI( @@ -432,7 +435,7 @@ def _find_smart_path(challbs, preferences, combinations): if not best_combo: msg = ("Client does not support any combination of challenges that " "will satisfy the CA.") - logging.fatal(msg) + logger.fatal(msg) raise errors.AuthorizationError(msg) return best_combo diff --git a/letsencrypt/cli.py b/letsencrypt/cli.py index 08d594ab1..118eb6e39 100644 --- a/letsencrypt/cli.py +++ b/letsencrypt/cli.py @@ -71,6 +71,9 @@ More detailed help: +logger = logging.getLogger(__name__) + + def _account_init(args, config): # Prepare for init of Client if args.email is None: @@ -112,7 +115,7 @@ def _init_acme(config, acc, authenticator, installer): try: acme.register() except errors.LetsEncryptClientError as error: - logging.debug(error) + logger.debug(error) sys.exit("Unable to register an account with ACME server") return acme @@ -235,11 +238,11 @@ def config_changes(unused_args, config, unused_plugins): def plugins_cmd(args, config, plugins): # TODO: Use IDiplay rathern than print """List server software plugins.""" - logging.debug("Expected interfaces: %s", args.ifaces) + logger.debug("Expected interfaces: %s", args.ifaces) ifaces = [] if args.ifaces is None else args.ifaces filtered = plugins.ifaces(ifaces) - logging.debug("Filtered plugins: %r", filtered) + logger.debug("Filtered plugins: %r", filtered) if not args.init and not args.prepare: print str(filtered) @@ -247,7 +250,7 @@ def plugins_cmd(args, config, plugins): # TODO: Use IDiplay rathern than print filtered.init(config) verified = filtered.verify(ifaces) - logging.debug("Verified plugins: %r", verified) + logger.debug("Verified plugins: %r", verified) if not args.prepare: print str(verified) @@ -255,7 +258,7 @@ def plugins_cmd(args, config, plugins): # TODO: Use IDiplay rathern than print verified.prepare() available = verified.available() - logging.debug("Prepared plugins: %s", available) + logger.debug("Prepared plugins: %s", available) print str(available) @@ -607,8 +610,8 @@ def _setup_logging(args): root_logger.addHandler(handler) root_logger.addHandler(file_handler) - logging.debug("Root logging level set at %d", level) - logging.info("Saving debug log to %s", log_file_name) + logger.debug("Root logging level set at %d", level) + logger.info("Saving debug log to %s", log_file_name) def main(cli_args=sys.argv[1:]): @@ -634,8 +637,8 @@ def main(cli_args=sys.argv[1:]): _setup_logging(args) # do not log `args`, as it contains sensitive data (e.g. revoke --key)! - logging.debug("Arguments: %r", cli_args) - logging.debug("Discovered plugins: %r", plugins) + logger.debug("Arguments: %r", cli_args) + logger.debug("Discovered plugins: %r", plugins) # Reporter report = reporter.Reporter() @@ -643,7 +646,7 @@ def main(cli_args=sys.argv[1:]): atexit.register(report.atexit_print_messages) if not os.geteuid() == 0: - logging.warning( + logger.warning( "Root (sudo) is required to run most of letsencrypt functionality.") # check must be done after arg parsing as --help should work # w/o root; on the other hand, e.g. "letsencrypt run diff --git a/letsencrypt/client.py b/letsencrypt/client.py index 5c54835f8..c4f5507f3 100644 --- a/letsencrypt/client.py +++ b/letsencrypt/client.py @@ -28,6 +28,9 @@ from letsencrypt.display import ops as display_ops from letsencrypt.display import enhancements +logger = logging.getLogger(__name__) + + class Client(object): """ACME protocol client. @@ -145,12 +148,12 @@ class Client(object): if self.auth_handler is None: msg = ("Unable to obtain certificate because authenticator is " "not set.") - logging.warning(msg) + logger.warning(msg) raise errors.Error(msg) if self.account.regr is None: raise errors.Error("Please register with the ACME server first.") - logging.debug("CSR: %s, domains: %s", csr, domains) + logger.debug("CSR: %s, domains: %s", csr, domains) authzr = self.auth_handler.get_authorizations(domains) certr = self.network.request_issuance( @@ -238,7 +241,7 @@ class Client(object): if (cli_config.config_dir != constants.CLI_DEFAULTS["config_dir"] or cli_config.work_dir != constants.CLI_DEFAULTS["work_dir"]): - logging.warning( + logger.warning( "Non-standard path(s), might not work with crontab installed " "by your operating system package manager") @@ -308,8 +311,8 @@ class Client(object): cert_file.write(cert_pem) finally: cert_file.close() - logging.info("Server issued certificate; certificate written to %s", - act_cert_path) + logger.info("Server issued certificate; certificate written to %s", + act_cert_path) if chain_cert is not None: chain_file, act_chain_path = le_util.unique_file( @@ -321,7 +324,7 @@ class Client(object): finally: chain_file.close() - logging.info("Cert chain written to %s", act_chain_path) + logger.info("Cert chain written to %s", act_chain_path) # This expects a valid chain file cert_chain_abspath = os.path.abspath(act_chain_path) @@ -338,8 +341,8 @@ class Client(object): """ if self.installer is None: - logging.warning("No installer specified, client is unable to deploy" - "the certificate") + logger.warning("No installer specified, client is unable to deploy" + "the certificate") raise errors.Error("No installer available") chain_path = None if chain_path is None else os.path.abspath(chain_path) @@ -374,8 +377,8 @@ class Client(object): """ if self.installer is None: - logging.warning("No installer is specified, there isn't any " - "configuration to enhance.") + logger.warning("No installer is specified, there isn't any " + "configuration to enhance.") raise errors.Error("No installer available") if redirect is None: @@ -395,7 +398,7 @@ class Client(object): try: self.installer.enhance(dom, "redirect") except errors.ConfiguratorError: - logging.warn("Unable to perform redirect for %s", dom) + logger.warn("Unable to perform redirect for %s", dom) self.installer.save("Add Redirects") self.installer.restart() diff --git a/letsencrypt/crypto_util.py b/letsencrypt/crypto_util.py index 943fd27eb..82b1b4867 100644 --- a/letsencrypt/crypto_util.py +++ b/letsencrypt/crypto_util.py @@ -18,6 +18,9 @@ import OpenSSL from letsencrypt import le_util +logger = logging.getLogger(__name__) + + # High level functions def init_save_key(key_size, key_dir, keyname="key-letsencrypt.pem"): """Initializes and saves a privkey. @@ -40,7 +43,7 @@ def init_save_key(key_size, key_dir, keyname="key-letsencrypt.pem"): try: key_pem = make_key(key_size) except ValueError as err: - logging.exception(err) + logger.exception(err) raise err # Save file @@ -50,7 +53,7 @@ def init_save_key(key_size, key_dir, keyname="key-letsencrypt.pem"): key_f.write(key_pem) key_f.close() - logging.info("Generating key (%d bits): %s", key_size, key_path) + logger.info("Generating key (%d bits): %s", key_size, key_path) return le_util.Key(key_path, key_pem) @@ -78,7 +81,7 @@ def init_save_csr(privkey, names, path, csrname="csr-letsencrypt.pem"): csr_f.write(csr_pem) csr_f.close() - logging.info("Creating CSR: %s", csr_filename) + logger.info("Creating CSR: %s", csr_filename) return le_util.CSR(csr_filename, csr_der, "der") @@ -275,7 +278,7 @@ def _get_sans_from_cert_or_req( try: cert_or_req = load_func(typ, cert_or_req_str) except OpenSSL.crypto.Error as error: - logging.exception(error) + logger.exception(error) raise return _pyopenssl_cert_or_req_san(cert_or_req) diff --git a/letsencrypt/display/enhancements.py b/letsencrypt/display/enhancements.py index 6d7c78d7d..8edc72ba0 100644 --- a/letsencrypt/display/enhancements.py +++ b/letsencrypt/display/enhancements.py @@ -8,6 +8,8 @@ from letsencrypt import interfaces from letsencrypt.display import util as display_util +logger = logging.getLogger(__name__) + # Define a helper function to avoid verbose code util = zope.component.getUtility # pylint: disable=invalid-name @@ -28,7 +30,7 @@ def ask(enhancement): # Call the appropriate function based on the enhancement return DISPATCH[enhancement]() except KeyError: - logging.error("Unsupported enhancement given to ask(): %s", enhancement) + logger.error("Unsupported enhancement given to ask(): %s", enhancement) raise errors.Error("Unsupported Enhancement") diff --git a/letsencrypt/display/ops.py b/letsencrypt/display/ops.py index 1a1887b9a..71d2e80f6 100644 --- a/letsencrypt/display/ops.py +++ b/letsencrypt/display/ops.py @@ -8,6 +8,8 @@ from letsencrypt import interfaces from letsencrypt.display import util as display_util +logger = logging.getLogger(__name__) + # Define a helper function to avoid verbose code util = zope.component.getUtility # pylint: disable=invalid-name @@ -70,7 +72,7 @@ def pick_plugin(config, default, plugins, question, ifaces): prepared = verified.available() if len(prepared) > 1: - logging.debug("Multiple candidate plugins: %s", prepared) + logger.debug("Multiple candidate plugins: %s", prepared) plugin_ep = choose_plugin(prepared.values(), question) if plugin_ep is None: return None @@ -78,10 +80,10 @@ def pick_plugin(config, default, plugins, question, ifaces): return plugin_ep.init() elif len(prepared) == 1: plugin_ep = prepared.values()[0] - logging.debug("Single candidate plugin: %s", plugin_ep) + logger.debug("Single candidate plugin: %s", plugin_ep) return plugin_ep.init() else: - logging.debug("No candidate plugin") + logger.debug("No candidate plugin") return None @@ -143,7 +145,7 @@ def choose_names(installer): """ if installer is None: - logging.debug("No installer, picking names manually") + logger.debug("No installer, picking names manually") return _choose_names_manually() names = list(installer.get_all_names()) diff --git a/letsencrypt/plugins/disco.py b/letsencrypt/plugins/disco.py index 6b0d8e4f3..8c6777d81 100644 --- a/letsencrypt/plugins/disco.py +++ b/letsencrypt/plugins/disco.py @@ -10,6 +10,9 @@ from letsencrypt import errors from letsencrypt import interfaces +logger = logging.getLogger(__name__) + + class PluginEntryPoint(object): """Plugin entry point.""" @@ -70,7 +73,7 @@ class PluginEntryPoint(object): zope.interface.verify.verifyObject(iface, self.init()) except zope.interface.exceptions.BrokenImplementation: if iface.implementedBy(self.plugin_cls): - logging.debug( + logger.debug( "%s implements %s but object does " "not verify", self.plugin_cls, iface.__name__) return False @@ -80,7 +83,7 @@ class PluginEntryPoint(object): def prepared(self): """Has the plugin been prepared already?""" if not self.initialized: - logging.debug(".prepared called on uninitialized %r", self) + logger.debug(".prepared called on uninitialized %r", self) return self._prepared is not None def prepare(self): @@ -90,10 +93,10 @@ class PluginEntryPoint(object): try: self._initialized.prepare() except errors.MisconfigurationError as error: - logging.debug("Misconfigured %r: %s", self, error) + logger.debug("Misconfigured %r: %s", self, error) self._prepared = error except errors.NoInstallationError as error: - logging.debug("No installation (%r): %s", self, error) + logger.debug("No installation (%r): %s", self, error) self._prepared = error else: self._prepared = True @@ -149,7 +152,7 @@ class PluginsRegistry(collections.Mapping): if interfaces.IPluginFactory.providedBy(plugin_ep.plugin_cls): plugins[plugin_ep.name] = plugin_ep else: # pragma: no cover - logging.warning( + logger.warning( "%r does not provide IPluginFactory, skipping", plugin_ep) return cls(plugins) diff --git a/letsencrypt/plugins/manual.py b/letsencrypt/plugins/manual.py index c4c7b890a..b16665581 100644 --- a/letsencrypt/plugins/manual.py +++ b/letsencrypt/plugins/manual.py @@ -14,6 +14,9 @@ from letsencrypt import interfaces from letsencrypt.plugins import common +logger = logging.getLogger(__name__) + + class ManualAuthenticator(common.Plugin): """Manual Authenticator. @@ -120,17 +123,17 @@ binary for temporary key/certificate generation.""".replace("\n", "") def _verify(self, achall, chall_response): # pylint: disable=no-self-use uri = chall_response.uri(achall.domain) - logging.debug("Verifying %s...", uri) + logger.debug("Verifying %s...", uri) try: response = requests.get(uri, verify=False) except requests.exceptions.ConnectionError as error: - logging.exception(error) + logger.exception(error) return False ret = response.text == achall.token if not ret: - logging.error("Unable to verify %s! Expected: %r, returned: %r.", - uri, achall.token, response.text) + logger.error("Unable to verify %s! Expected: %r, returned: %r.", + uri, achall.token, response.text) return ret diff --git a/letsencrypt/reporter.py b/letsencrypt/reporter.py index dc3859535..0c4a7b378 100644 --- a/letsencrypt/reporter.py +++ b/letsencrypt/reporter.py @@ -11,6 +11,9 @@ import zope.interface from letsencrypt import interfaces +logger = logging.getLogger(__name__) + + class Reporter(object): """Collects and displays information to the user. @@ -48,7 +51,7 @@ class Reporter(object): """ assert self.HIGH_PRIORITY <= priority <= self.LOW_PRIORITY self.messages.put(self._msg_type(priority, msg, on_crash)) - logging.info("Reporting to user: %s", msg) + logger.info("Reporting to user: %s", msg) def atexit_print_messages(self, pid=os.getpid()): """Function to be registered with atexit to print messages. diff --git a/letsencrypt/reverter.py b/letsencrypt/reverter.py index 72a6c0b67..a20ebb8dc 100644 --- a/letsencrypt/reverter.py +++ b/letsencrypt/reverter.py @@ -14,6 +14,9 @@ from letsencrypt import le_util from letsencrypt.display import util as display_util +logger = logging.getLogger(__name__) + + class Reverter(object): """Reverter Class - save and revert configuration checkpoints. @@ -38,8 +41,8 @@ class Reverter(object): self._recover_checkpoint(self.config.temp_checkpoint_dir) except errors.ReverterError: # We have a partial or incomplete recovery - logging.fatal("Incomplete or failed recovery for %s", - self.config.temp_checkpoint_dir) + logger.fatal("Incomplete or failed recovery for %s", + self.config.temp_checkpoint_dir) raise errors.ReverterError("Unable to revert temporary config") def rollback_checkpoints(self, rollback=1): @@ -56,26 +59,26 @@ class Reverter(object): try: rollback = int(rollback) except ValueError: - logging.error("Rollback argument must be a positive integer") + logger.error("Rollback argument must be a positive integer") raise errors.ReverterError("Invalid Input") # Sanity check input if rollback < 0: - logging.error("Rollback argument must be a positive integer") + logger.error("Rollback argument must be a positive integer") raise errors.ReverterError("Invalid Input") backups = os.listdir(self.config.backup_dir) backups.sort() if len(backups) < rollback: - logging.warning("Unable to rollback %d checkpoints, only %d exist", - rollback, len(backups)) + logger.warning("Unable to rollback %d checkpoints, only %d exist", + rollback, len(backups)) while rollback > 0 and backups: cp_dir = os.path.join(self.config.backup_dir, backups.pop()) try: self._recover_checkpoint(cp_dir) except errors.ReverterError: - logging.fatal("Failed to load checkpoint during rollback") + logger.fatal("Failed to load checkpoint during rollback") raise errors.ReverterError( "Unable to load checkpoint during rollback") rollback -= 1 @@ -93,8 +96,8 @@ class Reverter(object): backups.sort(reverse=True) if not backups: - logging.info("The Let's Encrypt client has not saved any backups " - "of your configuration") + logger.info("The Let's Encrypt client has not saved any backups " + "of your configuration") return # Make sure there isn't anything unexpected in the backup folder # There should only be timestamped (float) directories @@ -177,7 +180,7 @@ class Reverter(object): if filename not in existing_filepaths: # Tag files with index so multiple files can # have the same filename - logging.debug("Creating backup of %s", filename) + logger.debug("Creating backup of %s", filename) try: shutil.copy2(filename, os.path.join( cp_dir, os.path.basename(filename) + "_" + str(idx))) @@ -185,7 +188,7 @@ class Reverter(object): # http://stackoverflow.com/questions/4726260/effective-use-of-python-shutil-copy2 except IOError: op_fd.close() - logging.error( + logger.error( "Unable to add file %s to checkpoint %s", filename, cp_dir) raise errors.ReverterError( @@ -234,7 +237,7 @@ class Reverter(object): os.path.basename(path) + "_" + str(idx)), path) except (IOError, OSError): # This file is required in all checkpoints. - logging.error("Unable to recover files from %s", cp_dir) + logger.error("Unable to recover files from %s", cp_dir) raise errors.ReverterError( "Unable to recover files from %s" % cp_dir) @@ -244,7 +247,7 @@ class Reverter(object): try: shutil.rmtree(cp_dir) except OSError: - logging.error("Unable to remove directory: %s", cp_dir) + logger.error("Unable to remove directory: %s", cp_dir) raise errors.ReverterError( "Unable to remove directory: %s" % cp_dir) @@ -318,7 +321,7 @@ class Reverter(object): if path not in ex_files: new_fd.write("{0}{1}".format(path, os.linesep)) except (IOError, OSError): - logging.error("Unable to register file creation(s) - %s", files) + logger.error("Unable to register file creation(s) - %s", files) raise errors.ReverterError( "Unable to register file creation(s) - {0}".format(files)) finally: @@ -344,9 +347,9 @@ class Reverter(object): self._recover_checkpoint(self.config.in_progress_dir) except errors.ReverterError: # We have a partial or incomplete recovery - logging.fatal("Incomplete or failed recovery for IN_PROGRESS " - "checkpoint - %s", - self.config.in_progress_dir) + logger.fatal("Incomplete or failed recovery for IN_PROGRESS " + "checkpoint - %s", + self.config.in_progress_dir) raise errors.ReverterError( "Incomplete or failed recovery for IN_PROGRESS checkpoint " "- %s" % self.config.in_progress_dir) @@ -376,12 +379,12 @@ class Reverter(object): if os.path.lexists(path): os.remove(path) else: - logging.warning( + logger.warning( "File: %s - Could not be found to be deleted%s" "LE probably shut down unexpectedly", os.linesep, path) except (IOError, OSError): - logging.fatal( + logger.fatal( "Unable to remove filepaths contained within %s", file_list) raise errors.ReverterError( "Unable to remove filepaths contained within " @@ -422,7 +425,7 @@ class Reverter(object): shutil.move(changes_since_tmp_path, changes_since_path) except (IOError, OSError): - logging.error("Unable to finalize checkpoint - adding title") + logger.error("Unable to finalize checkpoint - adding title") raise errors.ReverterError("Unable to add title") self._timestamp_progress_dir() @@ -445,7 +448,7 @@ class Reverter(object): cur_time += .01 # After 10 attempts... something is probably wrong here... - logging.error( + logger.error( "Unable to finalize checkpoint, %s -> %s", self.config.in_progress_dir, final_dir) raise errors.ReverterError( diff --git a/letsencrypt/revoker.py b/letsencrypt/revoker.py index a3ea543fb..9faf9339c 100644 --- a/letsencrypt/revoker.py +++ b/letsencrypt/revoker.py @@ -26,6 +26,9 @@ from letsencrypt.display import util as display_util from letsencrypt.display import revocation +logger = logging.getLogger(__name__) + + class Revoker(object): """A revocation class for LE. @@ -97,7 +100,7 @@ class Revoker(object): if certs: self._safe_revoke(certs) else: - logging.info("No certificates using the authorized key were found.") + logger.info("No certificates using the authorized key were found.") def revoke_from_cert(self, cert_path): """Revoke a certificate by specifying a file path. @@ -121,7 +124,7 @@ class Revoker(object): self._safe_revoke([cert]) return - logging.info("Associated ACME certificate was not found.") + logger.info("Associated ACME certificate was not found.") def revoke_from_menu(self): """List trusted Let's Encrypt certificates.""" @@ -143,7 +146,7 @@ class Revoker(object): else: return else: - logging.info( + logger.info( "There are not any trusted Let's Encrypt " "certificates for this server.") return @@ -219,7 +222,7 @@ class Revoker(object): self._acme_revoke(cert) except errors.Error: # TODO: Improve error handling when networking is set... - logging.error( + logger.error( "Unable to revoke cert:%s%s", os.linesep, str(cert)) success_list.append(cert) revocation.success_revocation(cert) diff --git a/letsencrypt/tests/reverter_test.py b/letsencrypt/tests/reverter_test.py index dda867e4f..f2615453a 100644 --- a/letsencrypt/tests/reverter_test.py +++ b/letsencrypt/tests/reverter_test.py @@ -175,7 +175,7 @@ class ReverterCheckpointLocalTest(unittest.TestCase): self.assertRaises( errors.ReverterError, self.reverter.revert_temporary_config) - @mock.patch("letsencrypt.reverter.logging.warning") + @mock.patch("letsencrypt.reverter.logger.warning") def test_recover_checkpoint_missing_new_files(self, mock_warn): self.reverter.register_file_creation( True, os.path.join(self.dir1, "missing_file.txt")) @@ -303,10 +303,10 @@ class TestFullCheckpointsReverter(unittest.TestCase): self.assertRaises( errors.ReverterError, self.reverter.finalize_checkpoint, "Title") - @mock.patch("letsencrypt.reverter.logging") - def test_rollback_too_many(self, mock_logging): + @mock.patch("letsencrypt.reverter.logger") + def test_rollback_too_many(self, mock_logger): self.reverter.rollback_checkpoints(1) - self.assertEqual(mock_logging.warning.call_count, 1) + self.assertEqual(mock_logger.warning.call_count, 1) def test_multi_rollback(self): config3 = self._setup_three_checkpoints() @@ -327,10 +327,10 @@ class TestFullCheckpointsReverter(unittest.TestCase): # Make sure notification is output self.assertEqual(mock_output().notification.call_count, 1) - @mock.patch("letsencrypt.reverter.logging") - def test_view_config_changes_no_backups(self, mock_logging): + @mock.patch("letsencrypt.reverter.logger") + def test_view_config_changes_no_backups(self, mock_logger): self.reverter.view_config_changes() - self.assertTrue(mock_logging.info.call_count > 0) + self.assertTrue(mock_logger.info.call_count > 0) def test_view_config_changes_bad_backups_dir(self): # There shouldn't be any "in progess directories when this is called diff --git a/letsencrypt/tests/revoker_test.py b/letsencrypt/tests/revoker_test.py index 490ff9f01..893865ce9 100644 --- a/letsencrypt/tests/revoker_test.py +++ b/letsencrypt/tests/revoker_test.py @@ -162,7 +162,7 @@ class RevokerTest(RevokerBase): self.assertEqual(mock_net.call_count, 1) self.assertEqual(mock_display.more_info_cert.call_count, 1) - @mock.patch("letsencrypt.revoker.logging") + @mock.patch("letsencrypt.revoker.logger") @mock.patch("letsencrypt.network.Network.revoke") @mock.patch("letsencrypt.revoker.revocation") def test_revoke_by_menu_delete_all(self, mock_display, mock_net, mock_log): @@ -183,7 +183,7 @@ class RevokerTest(RevokerBase): @mock.patch("letsencrypt.revoker.revocation") @mock.patch("letsencrypt.revoker.Revoker._acme_revoke") - @mock.patch("letsencrypt.revoker.logging") + @mock.patch("letsencrypt.revoker.logger") def test_safe_revoke_acme_fail(self, mock_log, mock_revoke, mock_display): # pylint: disable=protected-access mock_revoke.side_effect = errors.Error diff --git a/letsencrypt_apache/configurator.py b/letsencrypt_apache/configurator.py index ee522d781..76f1069a0 100644 --- a/letsencrypt_apache/configurator.py +++ b/letsencrypt_apache/configurator.py @@ -26,6 +26,9 @@ from letsencrypt_apache import obj from letsencrypt_apache import parser +logger = logging.getLogger(__name__) + + # TODO: Augeas sections ie. , beginning and closing # tags need to be the same case, otherwise Augeas doesn't recognize them. # This is not able to be completely remedied by regular expressions because @@ -186,13 +189,13 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): if not path["cert_path"] or not path["cert_key"]: # Throw some can't find all of the directives error" - logging.warn( + logger.warn( "Cannot find a cert or key directive in %s. " "VirtualHost was not modified", vhost.path) # Presumably break here so that the virtualhost is not modified return False - logging.info("Deploying Certificate to VirtualHost %s", vhost.filep) + logger.info("Deploying Certificate to VirtualHost %s", vhost.filep) self.aug.set(path["cert_path"][0], cert_path) self.aug.set(path["cert_key"][0], key_path) @@ -406,7 +409,7 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): """ if not mod_loaded("ssl_module", self.conf('ctl')): - logging.info("Loading mod_ssl into Apache Server") + logger.info("Loading mod_ssl into Apache Server") enable_mod("ssl", self.conf('init-script'), self.conf('enmod')) @@ -414,8 +417,8 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): # Note: This could be made to also look for ip:443 combo # TODO: Need to search only open directives and IfMod mod_ssl.c if len(self.parser.find_dir(parser.case_i("Listen"), "443")) == 0: - logging.debug("No Listen 443 directive found. Setting the " - "Apache Server to Listen on port 443") + logger.debug("No Listen 443 directive found. Setting the " + "Apache Server to Listen on port 443") path = self.parser.add_dir_to_ifmodssl( parser.get_aug_path(self.parser.loc["listen"]), "Listen", "443") self.save_notes += "Added Listen 443 directive to %s\n" % path @@ -436,15 +439,15 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): for addr in vhost.addrs: if addr.get_addr() == "_default_": if not self.is_name_vhost(default_addr): - logging.debug("Setting all VirtualHosts on %s to be " - "name based vhosts", default_addr) + logger.debug("Setting all VirtualHosts on %s to be " + "name based vhosts", default_addr) self.add_name_vhost(default_addr) # No default addresses... so set each one individually for addr in vhost.addrs: if not self.is_name_vhost(addr): - logging.debug("Setting VirtualHost at %s to be a name " - "based virtual host", addr) + logger.debug("Setting VirtualHost at %s to be a name " + "based virtual host", addr) self.add_name_vhost(addr) def make_vhost_ssl(self, nonssl_vhost): # pylint: disable=too-many-locals @@ -482,7 +485,7 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): new_file.write(line) new_file.write("\n") except IOError: - logging.fatal("Error writing/reading to file in make_vhost_ssl") + logger.fatal("Error writing/reading to file in make_vhost_ssl") sys.exit(49) self.aug.load() @@ -505,7 +508,7 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): vh_p = self.aug.match("/files%s//* [label()=~regexp('%s')]" % (ssl_fp, parser.case_i("VirtualHost"))) if len(vh_p) != 1: - logging.error("Error: should only be one vhost in %s", avail_fp) + logger.error("Error: should only be one vhost in %s", avail_fp) sys.exit(1) self.parser.add_dir(vh_p[0], "SSLCertificateFile", @@ -515,7 +518,7 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): self.parser.add_dir(vh_p[0], "Include", self.parser.loc["ssl_options"]) # Log actions and create save notes - logging.info("Created an SSL vhost at %s", ssl_fp) + logger.info("Created an SSL vhost at %s", ssl_fp) self.save_notes += "Created ssl vhost at %s\n" % ssl_fp self.save() @@ -534,7 +537,7 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): if (ssl_vhost.filep != vhost.filep and addr in vhost.addrs and not self.is_name_vhost(addr)): self.add_name_vhost(addr) - logging.info("Enabling NameVirtualHosts on %s", addr) + logger.info("Enabling NameVirtualHosts on %s", addr) need_to_save = True if need_to_save: @@ -564,7 +567,7 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): raise errors.ConfiguratorError( "Unsupported enhancement: {}".format(enhancement)) except errors.ConfiguratorError: - logging.warn("Failed %s for %s", enhancement, domain) + logger.warn("Failed %s for %s", enhancement, domain) def _enable_redirect(self, ssl_vhost, unused_options): """Redirect all equivalent HTTP traffic to ssl_vhost. @@ -595,7 +598,7 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): general_v = self._general_vhost(ssl_vhost) if general_v is None: # Add virtual_server with redirect - logging.debug( + logger.debug( "Did not find http version of ssl virtual host... creating") return self._create_redirect_vhost(ssl_vhost) else: @@ -603,12 +606,12 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): exists, code = self._existing_redirect(general_v) if exists: if code == 0: - logging.debug("Redirect already added") - logging.info( + logger.debug("Redirect already added") + logger.info( "Configuration is already redirecting traffic to HTTPS") return else: - logging.info("Unknown redirect exists for this vhost") + logger.info("Unknown redirect exists for this vhost") raise errors.ConfiguratorError( "Unknown redirect already exists " "in {}".format(general_v.filep)) @@ -620,8 +623,8 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): (general_v.filep, ssl_vhost.filep)) self.save() - logging.info("Redirecting vhost in %s to ssl vhost in %s", - general_v.filep, ssl_vhost.filep) + logger.info("Redirecting vhost in %s to ssl vhost in %s", + general_v.filep, ssl_vhost.filep) def _existing_redirect(self, vhost): """Checks to see if existing redirect is in place. @@ -731,7 +734,7 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): # Write out file with open(redirect_filepath, "w") as redirect_fd: redirect_fd.write(redirect_file) - logging.info("Created redirect file: %s", redirect_filename) + logger.info("Created redirect file: %s", redirect_filename) self.aug.load() # Make a new vhost data structure and add it to the lists @@ -845,8 +848,8 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): # Can be removed once find directive can return ordered results if len(cert_path) != 1 or len(key_path) != 1: - logging.error("Too many cert or key directives in vhost %s", - vhost.filep) + logger.error("Too many cert or key directives in vhost %s", + vhost.filep) sys.exit(40) cert = os.path.abspath(self.aug.get(cert_path[0])) @@ -896,7 +899,7 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): self.reverter.register_file_creation(False, enabled_path) os.symlink(vhost.filep, enabled_path) vhost.enabled = True - logging.info("Enabling available site: %s", vhost.filep) + logger.info("Enabling available site: %s", vhost.filep) self.save_notes += "Enabled site %s\n" % vhost.filep return True return False @@ -924,12 +927,12 @@ class ApacheConfigurator(augeas_configurator.AugeasConfigurator): stderr=subprocess.PIPE) stdout, stderr = proc.communicate() except (OSError, ValueError): - logging.fatal("Unable to run /usr/sbin/apache2ctl configtest") + logger.fatal("Unable to run /usr/sbin/apache2ctl configtest") sys.exit(1) if proc.returncode != 0: # Enter recovery routine... - logging.error("Configtest failed\n%s\n%s", stdout, stderr) + logger.error("Configtest failed\n%s\n%s", stdout, stderr) return False return True @@ -1058,7 +1061,7 @@ def enable_mod(mod_name, apache_init_script, apache_enmod): stderr=open("/dev/null", "w")) apache_restart(apache_init_script) except (OSError, subprocess.CalledProcessError): - logging.exception("Error enabling mod_%s", mod_name) + logger.exception("Error enabling mod_%s", mod_name) sys.exit(1) @@ -1082,12 +1085,12 @@ def mod_loaded(module, apache_ctl): stdout, stderr = proc.communicate() except (OSError, ValueError): - logging.error( + logger.error( "Error accessing %s for loaded modules!", apache_ctl) raise errors.ConfiguratorError("Error accessing loaded modules") # Small errors that do not impede if proc.returncode != 0: - logging.warn("Error in checking loaded module list: %s", stderr) + logger.warn("Error in checking loaded module list: %s", stderr) raise errors.MisconfigurationError( "Apache is unable to check whether or not the module is " "loaded because Apache is misconfigured.") @@ -1120,11 +1123,11 @@ def apache_restart(apache_init_script): if proc.returncode != 0: # Enter recovery routine... - logging.error("Apache Restart Failed!\n%s\n%s", stdout, stderr) + logger.error("Apache Restart Failed!\n%s\n%s", stdout, stderr) return False except (OSError, ValueError): - logging.fatal( + logger.fatal( "Apache Restart Failed - Please Check the Configuration") sys.exit(1) diff --git a/letsencrypt_apache/dvsni.py b/letsencrypt_apache/dvsni.py index 5ff09aa50..5a9f8bc77 100644 --- a/letsencrypt_apache/dvsni.py +++ b/letsencrypt_apache/dvsni.py @@ -7,6 +7,9 @@ from letsencrypt.plugins import common from letsencrypt_apache import parser +logger = logging.getLogger(__name__) + + class ApacheDvsni(common.Dvsni): """Class performs DVSNI challenges within the Apache configurator. @@ -58,7 +61,7 @@ class ApacheDvsni(common.Dvsni): for achall in self.achalls: vhost = self.configurator.choose_vhost(achall.domain) if vhost is None: - logging.error( + logger.error( "No vhost exists with servername or alias of: %s. " "No _default_:443 vhost exists. Please specify servernames " "in the Apache config", achall.domain) diff --git a/letsencrypt_apache/parser.py b/letsencrypt_apache/parser.py index 5483b96ba..caec69b57 100644 --- a/letsencrypt_apache/parser.py +++ b/letsencrypt_apache/parser.py @@ -187,7 +187,7 @@ class ApacheParser(object): # validChars = re.compile("[a-zA-Z0-9.*?_-/]*") # matchObj = validChars.match(arg) # if matchObj.group() != arg: - # logging.error("Error: Invalid regexp characters in %s", arg) + # logger.error("Error: Invalid regexp characters in %s", arg) # return [] # Standardize the include argument based on server root diff --git a/letsencrypt_nginx/configurator.py b/letsencrypt_nginx/configurator.py index 29fa8cd16..e86e58d30 100644 --- a/letsencrypt_nginx/configurator.py +++ b/letsencrypt_nginx/configurator.py @@ -26,6 +26,9 @@ from letsencrypt_nginx import obj from letsencrypt_nginx import parser +logger = logging.getLogger(__name__) + + class NginxConfigurator(common.Plugin): # pylint: disable=too-many-instance-attributes,too-many-public-methods """Nginx configurator. @@ -128,10 +131,10 @@ class NginxConfigurator(common.Plugin): try: self.parser.add_server_directives(vhost.filep, vhost.names, directives, True) - logging.info("Deployed Certificate to VirtualHost %s for %s", - vhost.filep, vhost.names) + logger.info("Deployed Certificate to VirtualHost %s for %s", + vhost.filep, vhost.names) except errors.MisconfigurationError: - logging.warn( + logger.warn( "Cannot find a cert or key directive in %s for %s. " "VirtualHost was not modified.", vhost.filep, vhost.names) # Presumably break here so that the virtualhost is not modified @@ -320,7 +323,7 @@ class NginxConfigurator(common.Plugin): raise errors.ConfiguratorError( "Unsupported enhancement: {0}".format(enhancement)) except errors.ConfiguratorError: - logging.warn("Failed %s for %s", enhancement, domain) + logger.warn("Failed %s for %s", enhancement, domain) ###################################### # Nginx server management (IInstaller) @@ -348,12 +351,12 @@ class NginxConfigurator(common.Plugin): stderr=subprocess.PIPE) stdout, stderr = proc.communicate() except (OSError, ValueError): - logging.fatal("Unable to run nginx config test") + logger.fatal("Unable to run nginx config test") sys.exit(1) if proc.returncode != 0: # Enter recovery routine... - logging.error("Config test failed\n%s\n%s", stdout, stderr) + logger.error("Config test failed\n%s\n%s", stdout, stderr) return False return True @@ -566,11 +569,11 @@ def nginx_restart(nginx_ctl): if nginx_proc.returncode != 0: # Enter recovery routine... - logging.error("Nginx Restart Failed!\n%s\n%s", stdout, stderr) + logger.error("Nginx Restart Failed!\n%s\n%s", stdout, stderr) return False except (OSError, ValueError): - logging.fatal("Nginx Restart Failed - Please Check the Configuration") + logger.fatal("Nginx Restart Failed - Please Check the Configuration") sys.exit(1) return True diff --git a/letsencrypt_nginx/dvsni.py b/letsencrypt_nginx/dvsni.py index b8f9e328a..53221614f 100644 --- a/letsencrypt_nginx/dvsni.py +++ b/letsencrypt_nginx/dvsni.py @@ -10,6 +10,9 @@ from letsencrypt_nginx import obj from letsencrypt_nginx import nginxparser +logger = logging.getLogger(__name__) + + class NginxDvsni(common.Dvsni): """Class performs DVSNI challenges within the Nginx configurator. @@ -49,7 +52,7 @@ class NginxDvsni(common.Dvsni): for achall in self.achalls: vhost = self.configurator.choose_vhost(achall.domain) if vhost is None: - logging.error( + logger.error( "No nginx vhost exists with server_name matching: %s. " "Please specify server_names in the Nginx config.", achall.domain) diff --git a/letsencrypt_nginx/parser.py b/letsencrypt_nginx/parser.py index 6b52dfc15..dc82918f9 100644 --- a/letsencrypt_nginx/parser.py +++ b/letsencrypt_nginx/parser.py @@ -11,6 +11,9 @@ from letsencrypt_nginx import obj from letsencrypt_nginx import nginxparser +logger = logging.getLogger(__name__) + + class NginxParser(object): """Class handles the fine details of parsing the Nginx Configuration. @@ -161,9 +164,9 @@ class NginxParser(object): self.parsed[item] = parsed trees.append(parsed) except IOError: - logging.warn("Could not open file: %s", item) + logger.warn("Could not open file: %s", item) except pyparsing.ParseException: - logging.debug("Could not parse file: %s", item) + logger.debug("Could not parse file: %s", item) return trees def _set_locations(self, ssl_options): @@ -213,7 +216,7 @@ class NginxParser(object): with open(filename, 'w') as _file: nginxparser.dump(tree, _file) except IOError: - logging.error("Could not open file for writing: %s", filename) + logger.error("Could not open file for writing: %s", filename) def _has_server_names(self, entry, names): """Checks if a server block has the given set of server_names. This