updated logging for tests

circle/manager/scheduler.py

@@ -15,18 +15,18 @@
 # You should have received a copy of the GNU General Public License along
 # with CIRCLE.  If not, see <http://www.gnu.org/licenses/>.
 
-import random
 import datetime
+import json
+import random
+from logging import getLogger
 
+from django.conf import settings
 from django.core.cache import cache
-from django.utils.translation import ugettext_noop
 from django.utils import timezone
-from django.conf import settings
+from django.utils.translation import ugettext_noop
 
-from common.models import HumanReadableException
-from logging import getLogger
 from circle.settings.base import SCHEDULER_METHOD
-
+from common.models import HumanReadableException
 
 logger = getLogger(__name__)
 
@@ -93,7 +93,9 @@ def common_random(instance, nodes):
 def advanced_with_time_stamp(instance, nodes):
     nodes = common_select(instance, nodes)
     nodes.sort(key=sorting_key, reverse=True)
-    logger.info('SCHEDLOG: %s', nodes)
+    logger.info("SCHEDLOG: {}".format(json.dumps({
+        "event": "after_sort", 
+        "list": map(lambda node: unicode(node), nodes)})))
     result = nodes[0]
     return result
 
@@ -110,8 +112,10 @@ def select_node(instance, nodes):
     else:  # Default method is the random
         result = common_random(instance, nodes)
 
-    logger.info('SCHEDLOG: Scheduler method: %s selected', unicode(SCHEDULER_METHOD))
-    logger.info('SCHEDLOG: select_node: %s for %s', unicode(result), unicode(instance))
+    logger.info("SCHEDLOG: {}".format(json.dumps(
+        {"event": "select",
+         "node": unicode(result),
+          "vm": unicode(instance)})))
 
     set_time_stamp(result)
 
@@ -127,17 +131,26 @@ def sorting_key(node):
         key = free_cpu_time(node) * corr
     else:
         key = free_ram(node) * corr
-    logger.info('SCHEDLOG: node: %s score: %s freecpu: %s freeram: %s', unicode(node), unicode(key), unicode(free_cpu_time(node)), unicode(free_ram(node)))
+    logger.info("SCHEDLOG: {}".format(json.dumps({
+        "event": "sort",
+        "node": unicode(node),
+        "sorting_key": unicode(key),
+        "free_cpu_time": unicode(free_cpu_time(node)),
+        "free_ram": unicode(free_ram(node)),
+        "last_scheduled_correction_factor": unicode(last_scheduled_correction_factor(node))})))
     return key
 
+
 def set_time_stamp(node):
     cache.set('time_stamp{}'.format(node.id), timezone.now())
 
+
 def get_time_stamp(node):
     time_stamp = cache.get('time_stamp{}'.format(node.id))
     if time_stamp:
         return time_stamp
-    return datetime.datetime(1970,1,1, tzinfo=timezone.get_current_timezone())
+    return datetime.datetime(1970, 1, 1, tzinfo=timezone.get_current_timezone())
+
 
 def last_scheduled_correction_factor(node):
     """Returns the time correction factor for a node.
@@ -149,13 +162,14 @@ def last_scheduled_correction_factor(node):
     factor = 0
     max_time_diff = settings.SCHEDULER_TIME_SENSITIVITY_IN_SECONDS
     current_time = timezone.now()
-    time_difference_in_seconds = (current_time - get_time_stamp(node)).total_seconds()
+    time_difference_in_seconds = (
+        current_time - get_time_stamp(node)).total_seconds()
     factor = time_difference_in_seconds/float(max_time_diff)
     if factor > 1:
         factor = 1
     elif factor < 0:
-        factor = 1 
-    logger.info('Scheduler set factor to %s', unicode(factor))   
+        factor = 1
+    logger.info('Scheduler set factor to %s', unicode(factor))
     return factor
 
 
@@ -205,8 +219,8 @@ def free_cpu_time(node):
         return weighted_value
     except TypeError as e:
         logger.exception('Got incorrect monitoring data for node %s. %s',
-                       unicode(node), unicode(e))
-        return 0 # will result lowest priority
+                         unicode(node), unicode(e))
+        return 0  # will result lowest priority
 
 
 def free_ram(node):
@@ -222,4 +236,4 @@ def free_ram(node):
     except TypeError as e:
         logger.exception('Got incorrect monitoring data for node %s. %s',
                          unicode(node), unicode(e))
-        return 0 # will result lowest priority
+        return 0  # will result lowest priority