add more logging, check for broken db connections
diff --git a/xos/synchronizers/base/event_loop.py b/xos/synchronizers/base/event_loop.py
index d9fc3ea..0f23c04 100644
--- a/xos/synchronizers/base/event_loop.py
+++ b/xos/synchronizers/base/event_loop.py
@@ -348,9 +348,11 @@
if (step_status[d] is STEP_STATUS_WORKING):
logger.info(" step %s wait on dep %s" % (step.__name__, d))
cond.wait()
+ logger.info(" step %s wait on dep %s cond returned" % (step.__name__, d))
elif step_status[d] == STEP_STATUS_OK:
go = True
else:
+ logger.info(" step %s has failed dep %s" % (step.__name__, d))
go = False
failed_dep = d
cond.release()
@@ -360,6 +362,7 @@
go = True
if (not go):
+ logger.info("Step %s skipped" % step.__name__)
self.consolePrint(bcolors.FAIL + "Step %r skipped on %r" % (step,failed_dep) + bcolors.ENDC)
# SMBAKER: sync_step was not defined here, so I changed
# this from 'sync_step' to 'step'. Verify.
@@ -415,7 +418,7 @@
if failed_objects:
self.failed_step_objects.update(failed_objects)
- logger.info("Step %r succeeded" % sync_step.__name__)
+ logger.info("Step %r succeeded, deletion=%s" % (sync_step.__name__, deletion))
self.consolePrint(bcolors.OKGREEN + "Step %r succeeded" % sync_step.__name__ + bcolors.ENDC)
my_status = STEP_STATUS_OK
self.update_run_time(sync_step,deletion)
@@ -461,36 +464,26 @@
self.run_once()
+ def check_db_connection_okay(self):
+ # django implodes if the database connection is closed by docker-compose
+ try:
+ diag = Diag.objects.filter(name="foo").first()
+ except Exception, e:
+ from django import db
+ if "connection already closed" in traceback.format_exc():
+ logger.error("XXX connection already closed")
+ try:
+# if db.connection:
+# db.connection.close()
+ db.close_connection()
+ except:
+ logger.log_exc("XXX we failed to fix the failure")
+ else:
+ logger.log_exc("XXX some other error")
+
def run_once(self):
try:
- # django implodes if the database connection is closed by docker-compose
- try:
- diag = Diag.objects.filter(name="foo").first()
- except Exception, e:
- from django import db
- if "connection already closed" in traceback.format_exc():
- logger.error("XXX connection already closed")
- try:
- if db.connection:
- db.connection.close()
- except:
- logger.error("XXX we failed to fix the failure(1)")
- traceback.print_exc()
- try:
- db.close_connection()
- except:
- logger.error("XXX we failed to fix the failure(2)")
- traceback.print_exc()
- try:
- if db.connection and db.connection.connection:
- db.connection.connection.close()
- db.connection.connection = None
- except:
- logger.error("XXX we failed to fix the failure(3)")
- traceback.print_exc()
- else:
- logger.error("XXX some other error")
- traceback.print_exc()
+ self.check_db_connection_okay()
loop_start = time.time()
error_map_file = getattr(Config(), "error_map_path", XOS_DIR + "/error_map.txt")
diff --git a/xos/synchronizers/base/syncstep.py b/xos/synchronizers/base/syncstep.py
index d505481..3ddf75e 100644
--- a/xos/synchronizers/base/syncstep.py
+++ b/xos/synchronizers/base/syncstep.py
@@ -141,6 +141,8 @@
def sync_record(self, o):
+ logger.info("Sync_record called for %s %s" % (o.__class__.__name__, str(o)))
+
try:
controller = o.get_controller()
controller_register = json.loads(controller.backend_register)
diff --git a/xos/synchronizers/model_policy.py b/xos/synchronizers/model_policy.py
index ef31d41..aa12092 100644
--- a/xos/synchronizers/model_policy.py
+++ b/xos/synchronizers/model_policy.py
@@ -3,10 +3,11 @@
import pdb
from generate.dependency_walker import *
from synchronizers.openstack import model_policies
-from xos.logger import logger
+from xos.logger import Logger, logging
from datetime import datetime
from django.utils import timezone
import time
+import traceback
from core.models import *
from django.db import reset_queries
from django.db.transaction import atomic
@@ -15,6 +16,8 @@
modelPolicyEnabled = True
bad_instances=[]
+logger = Logger(level=logging.INFO)
+
def EnableModelPolicy(x):
global modelPolicyEnabled
modelPolicyEnabled = x
@@ -40,9 +43,10 @@
if (save_fields):
d.save(update_fields=save_fields)
except AttributeError,e:
+ logger.log_exc("AttributeError in update_dep")
raise e
except Exception,e:
- logger.info('Could not save %r. Exception: %r'%(d,e), extra=d.tologdict())
+ logger.log_exc("Exception in update_dep")
def delete_if_inactive(d, o):
try:
@@ -75,7 +79,7 @@
try:
policy_handler = getattr(model_policies, policy_name, None)
- logger.error("POLICY HANDLER: %s %s" % (policy_name, policy_handler))
+ logger.info("MODEL POLICY: handler %s %s" % (policy_name, policy_handler))
if policy_handler is not None:
if (deleted):
try:
@@ -84,23 +88,45 @@
pass
else:
policy_handler.handle(instance)
+ logger.info("MODEL POLICY: completed handler %s %s" % (policy_name, policy_handler))
except:
- logger.log_exc("Model Policy Error:")
+ logger.log_exc("MODEL POLICY: Exception when running handler")
try:
instance.policed=timezone.now()
instance.save(update_fields=['policed'])
except:
- logging.error('Object %r is defective'%instance)
+ logger.log_exc('MODEL POLICY: Object %r is defective'%instance)
bad_instances.append(instance)
def noop(o,p):
pass
+def check_db_connection_okay():
+ # django implodes if the database connection is closed by docker-compose
+ from django import db
+ try:
+ db.connection.cursor()
+ #diag = Diag.objects.filter(name="foo").first()
+ except Exception, e:
+ if "connection already closed" in traceback.format_exc():
+ logger.error("XXX connection already closed")
+ try:
+# if db.connection:
+# db.connection.close()
+ db.close_connection()
+ except:
+ logger.log_exc("XXX we failed to fix the failure")
+ else:
+ logger.log_exc("XXX some other error")
+
def run_policy():
while (True):
start = time.time()
- run_policy_once()
+ try:
+ run_policy_once()
+ except:
+ logger.log_exc("MODEL_POLICY: Exception in run_policy()")
if (time.time()-start<1):
time.sleep(1)
@@ -110,6 +136,10 @@
objects = []
deleted_objects = []
+ logger.info("MODEL POLICY: run_policy_once()")
+
+ check_db_connection_okay()
+
for m in models:
res = m.objects.filter((Q(policed__lt=F('updated')) | Q(policed=None)) & Q(no_policy=False))
objects.extend(res)
@@ -137,4 +167,6 @@
reset_queries()
except:
# this shouldn't happen, but in case it does, catch it...
- logger.log_exc("exception in reset_queries")
+ logger.log_exc("MODEL POLICY: exception in reset_queries")
+
+ logger.info("MODEL POLICY: finished run_policy_once()")