From 635c404e6748232e6a440f328f67dbe8ce6e4cb3 Mon Sep 17 00:00:00 2001 From: aszlig Date: Fri, 16 May 2014 13:24:24 +0200 Subject: [PATCH 1/4] robot: Add debug logging to request methods. This should give the majority of information about what's being sent and received to and from the Robot and is mainly useful for debugging during development. Signed-off-by: aszlig --- hetzner/robot.py | 25 ++++++++++++++++++++++--- 1 file changed, 22 insertions(+), 3 deletions(-) diff --git a/hetzner/robot.py b/hetzner/robot.py index 4eeda08..7aa5804 100644 --- a/hetzner/robot.py +++ b/hetzner/robot.py @@ -2,6 +2,7 @@ import ssl import json import socket +import logging from base64 import b64encode from urllib import urlencode @@ -124,14 +125,16 @@ def login(self, user=None, passwd=None, force=False): " page".format(response.status)) data = {'user': self.user, 'password': self.passwd} - response = self.request('/login/check', data, xhr=False) + logging.debug("Logging in to Robot web frontend with user %s.", + self.user) + response = self.request('/login/check', data, xhr=False, log=False) if response.status != 302 or response.getheader('Location') is None: raise WebRobotError("Login to robot web interface failed.") self.logged_in = True - def request(self, path, data=None, xhr=True, method=None): + def request(self, path, data=None, xhr=True, method=None, log=True): """ Send a request to the web interface, using 'data' for urlencoded POST data. If 'data' is None (which it is by default), a GET request is sent @@ -139,6 +142,9 @@ def request(self, path, data=None, xhr=True, method=None): By default this method uses headers for XMLHttpRequests, so if the request should be an ordinary HTTP request, set 'xhr' to False. + + If 'log' is set to False, don't log anything containing data. This is + useful to prevent logging sensible information such as passwords. """ self.connect() @@ -158,15 +164,24 @@ def request(self, path, data=None, xhr=True, method=None): encoded = urlencode(data) headers['Content-Type'] = 'application/x-www-form-urlencoded' + if log: + logging.debug("Sending %s request to Robot web frontend " + "at %s with data %r.", + ("XHR " if xhr else "") + method, path, encoded) self.conn.request(method, path, encoded, headers) try: response = self.conn.getresponse() except ResponseNotReady: + logging.debug("Connection closed by Robot web frontend, retrying.") # Connection closed, so we need to reconnect. # FIXME: Try to avoid endless loops here! self.connect(force=True) - return self.request(path, data=data, xhr=xhr) + return self.request(path, data=data, xhr=xhr, log=log) + + if log: + logging.debug("Got response from web frontend with status %d.", + response.status) self.update_session(response) return response @@ -208,6 +223,8 @@ def request(self, method, path, data=None, allow_empty=False): if data is not None: headers['Content-Type'] = 'application/x-www-form-urlencoded' + logging.debug("Sending %s request to Robot at %s with data %r.", + method, path, data) response = self._request(method, path, data, headers) raw_data = response.read() if len(raw_data) == 0 and not allow_empty: @@ -221,6 +238,8 @@ def request(self, method, path, data=None, allow_empty=False): raise RobotError(msg.format(response.status, repr(raw_data))) else: data = None + logging.debug("Got response from Robot with status %d and data %r.", + response.status, data) if 200 <= response.status < 300: return data From 8cde0c1a0b0d1469d510d26f4438d53b722078eb Mon Sep 17 00:00:00 2001 From: aszlig Date: Wed, 9 Jul 2014 15:13:17 +0200 Subject: [PATCH 2/4] server: Add logging for observed_reboot(). This is one of the main reasons we want to have logging, because a "hetznerctl rescue " usually prints nothing until we either have a shell or we timed out waiting for the machine to come up. Signed-off-by: aszlig --- hetzner/server.py | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/hetzner/server.py b/hetzner/server.py index 99c5ff8..337bcdf 100644 --- a/hetzner/server.py +++ b/hetzner/server.py @@ -6,6 +6,7 @@ import string import subprocess import warnings +import logging from tempfile import mkdtemp from datetime import datetime @@ -457,17 +458,23 @@ def observed_reboot(self, patience=300, tries=None, manual=False): tries = ['soft', 'hard'] for mode in tries: + logging.info("Tring to reboot using the %r method.", mode) self.reboot(mode) - now = time.time() + start_time = time.time() + logging.info("Waiting for machine to become available.") while True: - if time.time() > now + patience: + current_time = time.time() + if current_time > start_time + patience: + logging.info("Machine didn't come up after %d seconds.", + patience) break is_up = self.check_ssh() time.sleep(1) if is_up and is_down: + logging.info("Machine just became available.") return elif not is_down: is_down = not is_up From 9b489681011d9d84d6b440105d9b10ed3a0999d6 Mon Sep 17 00:00:00 2001 From: aszlig Date: Wed, 9 Jul 2014 15:30:32 +0200 Subject: [PATCH 3/4] server: Use logger named after server number. This should make it easier to see which server the log message actually is for. Signed-off-by: aszlig --- hetzner/server.py | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/hetzner/server.py b/hetzner/server.py index 337bcdf..dbc3d12 100644 --- a/hetzner/server.py +++ b/hetzner/server.py @@ -381,6 +381,7 @@ def __init__(self, conn, result): self.subnets = SubnetManager(self.conn, self.ip) self.rdns = ReverseDNSManager(self.conn, self.ip) self._admin_account = None + self.logger = logging.getLogger("Server #{0}".format(self.number)) @property def admin(self): @@ -458,23 +459,25 @@ def observed_reboot(self, patience=300, tries=None, manual=False): tries = ['soft', 'hard'] for mode in tries: - logging.info("Tring to reboot using the %r method.", mode) + self.logger.info("Tring to reboot using the %r method.", mode) self.reboot(mode) start_time = time.time() - logging.info("Waiting for machine to become available.") + self.logger.info("Waiting for machine to become available.") while True: current_time = time.time() if current_time > start_time + patience: - logging.info("Machine didn't come up after %d seconds.", - patience) + self.logger.info( + "Machine didn't come up after %d seconds.", + patience + ) break is_up = self.check_ssh() time.sleep(1) if is_up and is_down: - logging.info("Machine just became available.") + self.logger.info("Machine just became available.") return elif not is_down: is_down = not is_up From 3caa1eeb30149c435496b3c11ae06a96fd639e66 Mon Sep 17 00:00:00 2001 From: aszlig Date: Wed, 9 Jul 2014 15:32:11 +0200 Subject: [PATCH 4/4] hetznerctl: Enable logging for INFO messages. This should at least make observed_* actions a bit more visible and we can easily switch between logging levels. Signed-off-by: aszlig --- hetznerctl | 3 +++ 1 file changed, 3 insertions(+) diff --git a/hetznerctl b/hetznerctl index a8f3f72..df13a34 100755 --- a/hetznerctl +++ b/hetznerctl @@ -3,6 +3,9 @@ import sys import locale import warnings +import logging +logging.basicConfig(format='%(name)s: %(message)s', level=logging.INFO) + from os.path import expanduser from optparse import OptionParser, make_option from ConfigParser import RawConfigParser, Error