Add logging to API methods.

hetzner/robot.py

@@ -2,6 +2,7 @@
 import ssl
 import json
 import socket
+import logging
 
 from base64 import b64encode
 from urllib import urlencode
@@ -124,21 +125,26 @@ 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
         instead. A httplib.HTTPResponse is returned on success.
 
         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

hetzner/server.py

@@ -6,6 +6,7 @@
 import string
 import subprocess
 import warnings
+import logging
 
 from tempfile import mkdtemp
 from datetime import datetime
@@ -380,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):
@@ -457,17 +459,25 @@ def observed_reboot(self, patience=300, tries=None, manual=False):
                 tries = ['soft', 'hard']
 
         for mode in tries:
+            self.logger.info("Tring to reboot using the %r method.", mode)
             self.reboot(mode)
 
-            now = time.time()
+            start_time = time.time()
+            self.logger.info("Waiting for machine to become available.")
             while True:
-                if time.time() > now + patience:
+                current_time = time.time()
+                if current_time > start_time + 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:
+                    self.logger.info("Machine just became available.")
                     return
                 elif not is_down:
                     is_down = not is_up

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