core: use of the new core.log module:

/!\ this is a massive refactoring and was largely automated, it probably did bring some bugs /!\
This commit is contained in:
Goffi 2014-04-19 19:19:19 +02:00
commit 501bc92528

View file

@ -19,7 +19,8 @@
from sat.core.i18n import _
from sat.core import exceptions
from logging import debug, info, warning, error
from sat.core.log import getLogger
log = getLogger(__name__)
from twisted.enterprise import adbapi
from twisted.internet import defer
from collections import OrderedDict
@ -80,7 +81,7 @@ class SqliteStorage(object):
self.initialized = defer.Deferred() # triggered when memory is fully initialised and ready
self.profiles = {} # we keep cache for the profiles (key: profile name, value: profile id)
info(_("Connecting database"))
log.info(_("Connecting database"))
new_base = not os.path.exists(db_filename) # do we have to create the database ?
if new_base: # the dir may not exist if it's not the XDG recommended one
dir_ = os.path.dirname(db_filename)
@ -92,10 +93,10 @@ class SqliteStorage(object):
# XXX: foreign_keys activation doesn't seem to work, probably because of the multi-threading
# All the requests that need to use this feature should be run with runInteraction instead,
# so you can set the PRAGMA as it is done in self.deleteProfile
init_defer = self.dbpool.runOperation("PRAGMA foreign_keys = ON").addErrback(lambda x: error(_("Can't activate foreign keys")))
init_defer = self.dbpool.runOperation("PRAGMA foreign_keys = ON").addErrback(lambda x: log.error(_("Can't activate foreign keys")))
def getNewBaseSql():
info(_("The database is new, creating the tables"))
log.info(_("The database is new, creating the tables"))
database_creation = ["PRAGMA user_version=%d" % CURRENT_DB_VERSION]
database_creation.extend(Updater.createData2Raw(DATABASE_SCHEMAS['current']['CREATE']))
database_creation.extend(Updater.insertData2Raw(DATABASE_SCHEMAS['current']['INSERT']))
@ -109,7 +110,7 @@ class SqliteStorage(object):
if statements is None:
return defer.succeed(None)
debug("===== COMMITING STATEMENTS =====\n%s\n============\n\n" % '\n'.join(statements))
log.debug("===== COMMITING STATEMENTS =====\n%s\n============\n\n" % '\n'.join(statements))
d = self.dbpool.runInteraction(self._updateDb, tuple(statements))
return d
@ -166,7 +167,7 @@ class SqliteStorage(object):
@param name: name of the profile
@return: deferred triggered once profile is actually deleted"""
def deletionError(failure):
error(_("Can't delete profile [%s]") % name)
log.error(_("Can't delete profile [%s]") % name)
return failure
def delete(txn):
@ -176,7 +177,7 @@ class SqliteStorage(object):
return None
d = self.dbpool.runInteraction(delete)
d.addCallback(lambda ignore: info(_("Profile [%s] deleted") % name))
d.addCallback(lambda ignore: log.info(_("Profile [%s] deleted") % name))
d.addErrback(deletionError)
return d
@ -190,7 +191,7 @@ class SqliteStorage(object):
for param in result:
category, name, value = param
params_gen[(category, name)] = value
debug(_("loading general parameters from database"))
log.debug(_("loading general parameters from database"))
return self.dbpool.runQuery("SELECT category,name,value FROM param_gen").addCallback(fillParams)
def loadIndParams(self, params_ind, profile):
@ -203,7 +204,7 @@ class SqliteStorage(object):
for param in result:
category, name, value = param
params_ind[(category, name)] = value
debug(_("loading individual parameters from database"))
log.debug(_("loading individual parameters from database"))
d = self.dbpool.runQuery("SELECT category,name,value FROM param_ind WHERE profile_id=?", (self.profiles[profile], ))
d.addCallback(fillParams)
return d
@ -225,7 +226,7 @@ class SqliteStorage(object):
@param value: value to set
@return: deferred"""
d = self.dbpool.runQuery("REPLACE INTO param_gen(category,name,value) VALUES (?,?,?)", (category, name, value))
d.addErrback(lambda ignore: error(_("Can't set general parameter (%(category)s/%(name)s) in database" % {"category": category, "name": name})))
d.addErrback(lambda ignore: log.error(_("Can't set general parameter (%(category)s/%(name)s) in database" % {"category": category, "name": name})))
return d
def setIndParam(self, category, name, value, profile):
@ -236,7 +237,7 @@ class SqliteStorage(object):
@param profile: a profile which *must* exist
@return: deferred"""
d = self.dbpool.runQuery("REPLACE INTO param_ind(category,name,profile_id,value) VALUES (?,?,?,?)", (category, name, self.profiles[profile], value))
d.addErrback(lambda ignore: error(_("Can't set individual parameter (%(category)s/%(name)s) for [%(profile)s] in database" % {"category": category, "name": name, "profile": profile})))
d.addErrback(lambda ignore: log.error(_("Can't set individual parameter (%(category)s/%(name)s) for [%(profile)s] in database" % {"category": category, "name": name, "profile": profile})))
return d
#History
@ -256,7 +257,7 @@ class SqliteStorage(object):
d = self.dbpool.runQuery("INSERT INTO history(source, source_res, dest, dest_res, timestamp, message, type, extra, profile_id) VALUES (?,?,?,?,?,?,?,?,?)",
(from_jid.userhost(), from_jid.resource, to_jid.userhost(), to_jid.resource, timestamp or time(),
message, _type, extra_, self.profiles[profile]))
d.addErrback(lambda ignore: error(_("Can't save following message in history: from [%(from_jid)s] to [%(to_jid)s] ==> [%(message)s]" %
d.addErrback(lambda ignore: log.error(_("Can't save following message in history: from [%(from_jid)s] to [%(to_jid)s] ==> [%(message)s]" %
{"from_jid": from_jid.full(), "to_jid": to_jid.full(), "message": message})))
return d
@ -321,9 +322,9 @@ class SqliteStorage(object):
for private in result:
key, value = private
private_gen[key] = value
debug(_("loading general private values [namespace: %s] from database") % (namespace, ))
log.debug(_("loading general private values [namespace: %s] from database") % (namespace, ))
d = self.dbpool.runQuery("SELECT key,value FROM private_gen WHERE namespace=?", (namespace, )).addCallback(fillPrivates)
return d.addErrback(lambda x: debug(_("No data present in database for namespace %s") % namespace))
return d.addErrback(lambda x: log.debug(_("No data present in database for namespace %s") % namespace))
def loadIndPrivates(self, private_ind, namespace, profile):
"""Load individual private values
@ -336,10 +337,10 @@ class SqliteStorage(object):
for private in result:
key, value = private
private_ind[key] = value
debug(_("loading individual private values [namespace: %s] from database") % (namespace, ))
log.debug(_("loading individual private values [namespace: %s] from database") % (namespace, ))
d = self.dbpool.runQuery("SELECT key,value FROM private_ind WHERE namespace=? AND profile_id=?", (namespace, self.profiles[profile]))
d.addCallback(fillPrivates)
return d.addErrback(lambda x: debug(_("No data present in database for namespace %s") % namespace))
return d.addErrback(lambda x: log.debug(_("No data present in database for namespace %s") % namespace))
def setGenPrivate(self, namespace, key, value):
"""Save the general private value in database
@ -348,7 +349,7 @@ class SqliteStorage(object):
@param value: value to set
@return: deferred"""
d = self.dbpool.runQuery("REPLACE INTO private_gen(namespace,key,value) VALUES (?,?,?)", (namespace, key, value))
d.addErrback(lambda ignore: error(_("Can't set general private value (%(key)s) [namespace:%(namespace)s] in database" %
d.addErrback(lambda ignore: log.error(_("Can't set general private value (%(key)s) [namespace:%(namespace)s] in database" %
{"namespace": namespace, "key": key})))
return d
@ -360,7 +361,7 @@ class SqliteStorage(object):
@param profile: a profile which *must* exist
@return: deferred"""
d = self.dbpool.runQuery("REPLACE INTO private_ind(namespace,key,profile_id,value) VALUES (?,?,?,?)", (namespace, key, self.profiles[profile], value))
d.addErrback(lambda ignore: error(_("Can't set individual private value (%(key)s) [namespace: %(namespace)s] for [%(profile)s] in database" %
d.addErrback(lambda ignore: log.error(_("Can't set individual private value (%(key)s) [namespace: %(namespace)s] for [%(profile)s] in database" %
{"namespace": namespace, "key": key, "profile": profile})))
return d
@ -370,7 +371,7 @@ class SqliteStorage(object):
@param key: key of the private value
@return: deferred"""
d = self.dbpool.runQuery("DELETE FROM private_gen WHERE namespace=? AND key=?", (namespace, key))
d.addErrback(lambda ignore: error(_("Can't delete general private value (%(key)s) [namespace:%(namespace)s] in database" %
d.addErrback(lambda ignore: log.error(_("Can't delete general private value (%(key)s) [namespace:%(namespace)s] in database" %
{"namespace": namespace, "key": key})))
return d
@ -381,7 +382,7 @@ class SqliteStorage(object):
@param profile: a profile which *must* exist
@return: deferred"""
d = self.dbpool.runQuery("DELETE FROM private_ind WHERE namespace=? AND key=? AND profile=?)", (namespace, key, self.profiles[profile]))
d.addErrback(lambda ignore: error(_("Can't delete individual private value (%(key)s) [namespace: %(namespace)s] for [%(profile)s] in database" %
d.addErrback(lambda ignore: log.error(_("Can't delete individual private value (%(key)s) [namespace: %(namespace)s] for [%(profile)s] in database" %
{"namespace": namespace, "key": key, "profile": profile})))
return d
@ -395,9 +396,9 @@ class SqliteStorage(object):
for private in result:
key, value = private
private_gen[key] = pickle.loads(str(value))
debug(_("loading general private binary values [namespace: %s] from database") % (namespace, ))
log.debug(_("loading general private binary values [namespace: %s] from database") % (namespace, ))
d = self.dbpool.runQuery("SELECT key,value FROM private_gen_bin WHERE namespace=?", (namespace, )).addCallback(fillPrivates)
return d.addErrback(lambda x: debug(_("No binary data present in database for namespace %s") % namespace))
return d.addErrback(lambda x: log.debug(_("No binary data present in database for namespace %s") % namespace))
def loadIndPrivatesBinary(self, private_ind, namespace, profile):
"""Load individual private binary values
@ -410,10 +411,10 @@ class SqliteStorage(object):
for private in result:
key, value = private
private_ind[key] = pickle.loads(str(value))
debug(_("loading individual private binary values [namespace: %s] from database") % (namespace, ))
log.debug(_("loading individual private binary values [namespace: %s] from database") % (namespace, ))
d = self.dbpool.runQuery("SELECT key,value FROM private_ind_bin WHERE namespace=? AND profile_id=?", (namespace, self.profiles[profile]))
d.addCallback(fillPrivates)
return d.addErrback(lambda x: debug(_("No binary data present in database for namespace %s") % namespace))
return d.addErrback(lambda x: log.debug(_("No binary data present in database for namespace %s") % namespace))
def setGenPrivateBinary(self, namespace, key, value):
"""Save the general private binary value in database
@ -422,7 +423,7 @@ class SqliteStorage(object):
@param value: value to set
@return: deferred"""
d = self.dbpool.runQuery("REPLACE INTO private_gen_bin(namespace,key,value) VALUES (?,?,?)", (namespace, key, pickle.dumps(value, 0)))
d.addErrback(lambda ignore: error(_("Can't set general private binary value (%(key)s) [namespace:%(namespace)s] in database" %
d.addErrback(lambda ignore: log.error(_("Can't set general private binary value (%(key)s) [namespace:%(namespace)s] in database" %
{"namespace": namespace, "key": key})))
return d
@ -434,7 +435,7 @@ class SqliteStorage(object):
@param profile: a profile which *must* exist
@return: deferred"""
d = self.dbpool.runQuery("REPLACE INTO private_ind_bin(namespace,key,profile_id,value) VALUES (?,?,?,?)", (namespace, key, self.profiles[profile], pickle.dumps(value, 0)))
d.addErrback(lambda ignore: error(_("Can't set individual binary private value (%(key)s) [namespace: %(namespace)s] for [%(profile)s] in database" %
d.addErrback(lambda ignore: log.error(_("Can't set individual binary private value (%(key)s) [namespace: %(namespace)s] for [%(profile)s] in database" %
{"namespace": namespace, "key": key, "profile": profile})))
return d
@ -444,7 +445,7 @@ class SqliteStorage(object):
@param key: key of the private value
@return: deferred"""
d = self.dbpool.runQuery("DELETE FROM private_gen_bin WHERE namespace=? AND key=?", (namespace, key))
d.addErrback(lambda ignore: error(_("Can't delete general private binary value (%(key)s) [namespace:%(namespace)s] in database" %
d.addErrback(lambda ignore: log.error(_("Can't delete general private binary value (%(key)s) [namespace:%(namespace)s] in database" %
{"namespace": namespace, "key": key})))
return d
@ -455,7 +456,7 @@ class SqliteStorage(object):
@param profile: a profile which *must* exist
@return: deferred"""
d = self.dbpool.runQuery("DELETE FROM private_ind_bin WHERE namespace=? AND key=? AND profile=?)", (namespace, key, self.profiles[profile]))
d.addErrback(lambda ignore: error(_("Can't delete individual private binary value (%(key)s) [namespace: %(namespace)s] for [%(profile)s] in database" %
d.addErrback(lambda ignore: log.error(_("Can't delete individual private binary value (%(key)s) [namespace: %(namespace)s] for [%(profile)s] in database" %
{"namespace": namespace, "key": key, "profile": profile})))
return d
##Helper methods##
@ -521,7 +522,7 @@ class Updater(object):
if local_hash == current_hash:
if local_version != CURRENT_DB_VERSION:
warning(_("Your local schema is up-to-date, but database versions mismatch, fixing it..."))
log.warning(_("Your local schema is up-to-date, but database versions mismatch, fixing it..."))
yield self._setLocalVersion(CURRENT_DB_VERSION)
else:
# an update is needed
@ -531,17 +532,17 @@ class Updater(object):
if self._sat_version.endswith('D'):
# we are in a development version
update_data = self.generateUpdateData(local_sch, current_sch, False)
warning(_("There is a schema mismatch, but as we are on a dev version, database will be updated"))
log.warning(_("There is a schema mismatch, but as we are on a dev version, database will be updated"))
update_raw = self.update2raw(update_data, True)
defer.returnValue(update_raw)
else:
error(_(u"schema version is up-to-date, but local schema differ from expected current schema"))
log.error(_(u"schema version is up-to-date, but local schema differ from expected current schema"))
update_data = self.generateUpdateData(local_sch, current_sch, True)
warning(_(u"Here are the commands that should fix the situation, use at your own risk (do a backup before modifying database), you can go to SàT's MUC room at sat@chat.jabberfr.org for help\n### SQL###\n%s\n### END SQL ###\n") % u'\n'.join(("%s;" % statement for statement in self.update2raw(update_data))))
log.warning(_(u"Here are the commands that should fix the situation, use at your own risk (do a backup before modifying database), you can go to SàT's MUC room at sat@chat.jabberfr.org for help\n### SQL###\n%s\n### END SQL ###\n") % u'\n'.join(("%s;" % statement for statement in self.update2raw(update_data))))
raise exceptions.DatabaseError("Database mismatch")
else:
# Database is not up-to-date, we'll do the update
info(_("Database schema has changed, local database will be updated"))
log.info(_("Database schema has changed, local database will be updated"))
update_raw = []
for version in xrange(local_version+1, CURRENT_DB_VERSION+1):
try:
@ -612,12 +613,12 @@ class Updater(object):
schema_dict = {}
for create_statement in raw_statements:
if not create_statement.startswith("CREATE TABLE "):
warning("Unexpected statement, ignoring it")
log.warning("Unexpected statement, ignoring it")
continue
_create_statement = create_statement[13:]
table, raw_col_stats = _create_statement.split(' ',1)
if raw_col_stats[0] != '(' or raw_col_stats[-1] != ')':
warning("Unexpected statement structure, ignoring it")
log.warning("Unexpected statement structure, ignoring it")
continue
col_stats = [stmt.strip() for stmt in self.stmnt_regex.findall(raw_col_stats[1:-1])]
col_defs = []
@ -668,7 +669,7 @@ class Updater(object):
new_col_defs, new_constraints = new_data[table]
for obj in old_col_defs, old_constraints, new_col_defs, new_constraints:
if not isinstance(obj, tuple):
raise InternalError("Columns definitions must be tuples")
raise exceptions.InternalError("Columns definitions must be tuples")
defs_create, defs_delete, ignore = getChanges(set(old_col_defs), set(new_col_defs))
constraints_create, constraints_delete, ignore = getChanges(set(old_constraints), set(new_constraints))
created_col_names = set([name.split(' ',1)[0] for name in defs_create])
@ -706,7 +707,7 @@ class Updater(object):
drop.append(self.DROP_SQL % table)
if dev_version:
if drop:
info("Dev version, SQL NOT EXECUTED:\n--\n%s\n--\n" % "\n".join(drop))
log.info("Dev version, SQL NOT EXECUTED:\n--\n%s\n--\n" % "\n".join(drop))
else:
ret.extend(drop)
@ -717,7 +718,7 @@ class Updater(object):
cols_delete = update.get('cols delete', {})
for table in cols_delete:
info("Following columns in table [%s] are not needed anymore, but are kept for dev version: %s" % (table, ", ".join(cols_delete[table])))
log.info("Following columns in table [%s] are not needed anymore, but are kept for dev version: %s" % (table, ", ".join(cols_delete[table])))
cols_modify = update.get('cols modify', {})
for table in cols_modify: