fba/models/instances.py

   1 # Fedi API Block - An aggregator for fetching blocking data from fediverse nodes
   2 # Copyright (C) 2023 Free Software Foundation
   3 #
   4 # This program is free software: you can redistribute it and/or modify
   5 # it under the terms of the GNU Affero General Public License as published
   6 # by the Free Software Foundation, either version 3 of the License, or
   7 # (at your option) any later version.
   8 #
   9 # This program is distributed in the hope that it will be useful,
  10 # but WITHOUT ANY WARRANTY; without even the implied warranty of
  11 # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  12 # GNU Affero General Public License for more details.
  13 #
  14 # You should have received a copy of the GNU Affero General Public License
  15 # along with this program.  If not, see <https://www.gnu.org/licenses/>.
  16
  17 import logging
  18 import json
  19 import time
  20
  21 import requests
  22 import validators
  23
  24 from fba import database
  25 from fba import utils
  26
  27 from fba.helpers import blacklist
  28 from fba.helpers import cache
  29 from fba.helpers import config
  30 from fba.helpers import domain as domain_helper
  31 from fba.helpers import tidyup
  32
  33 from fba.http import federation
  34 from fba.http import network
  35
  36 from fba.models import error_log
  37
  38 logging.basicConfig(level=logging.INFO)
  39 logger = logging.getLogger(__name__)
  40 #logger.setLevel(logging.DEBUG)
  41
  42 # Found info from node, such as nodeinfo URL, detection mode that needs to be
  43 # written to database. Both arrays must be filled at the same time or else
  44 # update() will fail
  45 _pending = {
  46     # Detection mode
  47     # NULL means all detection methods have failed (maybe still reachable instance)
  48     "detection_mode"     : {},
  49     # Found nodeinfo URL
  50     "nodeinfo_url"       : {},
  51     # Found total peers
  52     "total_peers"        : {},
  53     # Found total blocks
  54     "total_blocks"       : {},
  55     # Obfuscated domains
  56     "obfuscated_blocks"  : {},
  57     # Last fetched instances
  58     "last_instance_fetch": {},
  59     # Last updated
  60     "last_updated"       : {},
  61     # Last blocked
  62     "last_blocked"       : {},
  63     # Last nodeinfo (fetched)
  64     "last_nodeinfo"      : {},
  65     # Last response time
  66     "last_response_time" : {},
  67     # Last status code
  68     "last_status_code"   : {},
  69     # Last error details
  70     "last_error_details" : {},
  71     # Wether obfuscation has been used
  72     "has_obfuscation"    : {},
  73     # Determined software
  74     "software"           : {},
  75 }
  76
  77 def _set_data(key: str, domain: str, value: any):
  78     logger.debug("key='%s',domain='%s',value[]='%s' - CALLED!", key, domain, type(value))
  79     domain_helper.raise_on(domain)
  80
  81     if not isinstance(key, str):
  82         raise ValueError(f"Parameter key[]='{type(key)}' is not of type 'str'")
  83     elif key == "":
  84         raise ValueError("Parameter 'key' is empty")
  85     elif not key in _pending:
  86         raise ValueError(f"key='{key}' not found in _pending")
  87     elif not utils.is_primitive(value):
  88         raise ValueError(f"value[]='{type(value)}' is not a primitive type")
  89
  90     # Set it
  91     _pending[key][domain] = value
  92
  93     logger.debug("EXIT!")
  94
  95 def has_pending(domain: str) -> bool:
  96     logger.debug("domain='%s' - CALLED!", domain)
  97     domain_helper.raise_on(domain)
  98
  99     if not is_registered(domain):
 100         raise ValueError(f"domain='{domain}' is not registered but function was invoked.")
 101
 102     has = False
 103     for key in _pending:
 104         logger.debug("key='%s',domain='%s',_pending[key]()=%d", key, domain, len(_pending[key]))
 105         if domain in _pending[key]:
 106             logger.debug("domain='%s' at key='%s' has pending data ...", domain, key)
 107             has = True
 108             break
 109
 110     logger.debug("has='%s' - EXIT!", has)
 111     return has
 112
 113 def update(domain: str):
 114     logger.debug("domain='%s' - CALLED!", domain)
 115     domain_helper.raise_on(domain)
 116
 117     if not is_registered(domain):
 118         raise Exception(f"domain='{domain}' cannot be updated while not being registered")
 119     elif not has_pending(domain):
 120         raise Exception(f"domain='{domain}' has no pending instance data, but function invoked")
 121
 122     logger.debug("Updating instance data for domain='%s' ...", domain)
 123     sql_string = ""
 124     fields = list()
 125     for key in _pending:
 126         logger.debug("Checking key='%s',domain='%s'", key, domain)
 127         if domain in _pending[key]:
 128             logger.debug("Adding '%s' for key='%s' ...", _pending[key][domain], key)
 129             fields.append(_pending[key][domain])
 130             sql_string += f" {key} = ?,"
 131
 132     logger.debug("sql_string(%d)='%s'", len(sql_string), sql_string)
 133     if sql_string == "":
 134         raise ValueError(f"No fields have been set, but function invoked, domain='{domain}'")
 135
 136     # Set last_updated to current timestamp
 137     fields.append(time.time())
 138
 139     # For WHERE statement
 140     logger.debug("Setting domain='%s' for WHERE statement ...", domain)
 141     fields.append(domain)
 142
 143     logger.debug("sql_string='%s',fields()=%d", sql_string, len(fields))
 144     sql_string = "UPDATE instances SET" + sql_string + " last_updated = ? WHERE domain = ? LIMIT 1"
 145
 146     logger.debug("Executing SQL: sql_string='%s',fields()=%d", sql_string, len(fields))
 147     database.cursor.execute(sql_string, fields)
 148
 149     logger.debug("rowcount=%d", database.cursor.rowcount)
 150     if database.cursor.rowcount == 0:
 151         raise Exception(f"Did not update any rows: domain='{domain}',fields()={len(fields)}")
 152
 153     logger.debug("Invoking commit() ...")
 154     database.connection.commit()
 155
 156     logger.debug("Deleting _pending for domain='%s'", domain)
 157     for key in _pending:
 158         logger.debug("domain='%s',key='%s'", domain, key)
 159         if domain in _pending[key]:
 160             logger.debug("Deleting key='%s',domain='%s' ...", key, domain)
 161             del _pending[key][domain]
 162
 163     logger.debug("EXIT!")
 164
 165 def add(domain: str, origin: str, command: str, path: str = None, software: str = None):
 166     logger.debug("domain='%s',origin='%s',command='%s',path='%s',software='%s' - CALLED!", domain, origin, command, path, software)
 167     domain_helper.raise_on(domain)
 168
 169     if not isinstance(origin, str) and origin is not None:
 170         raise ValueError(f"origin[]='{type(origin)}' is not of type 'str'")
 171     elif origin == "":
 172         raise ValueError("Parameter 'origin' is empty")
 173     elif not isinstance(command, str):
 174         raise ValueError(f"command[]='{type(command)}' is not of type 'str'")
 175     elif command == "":
 176         raise ValueError("Parameter 'command' is empty")
 177     elif not isinstance(path, str) and path is not None:
 178         raise ValueError(f"path[]='{type(path)}' is not of type 'str'")
 179     elif path == "":
 180         raise ValueError("Parameter 'path' is empty")
 181     elif not path.startswith("/"):
 182         raise ValueError("path='{path}' does not start with / but should")
 183     elif not isinstance(software, str) and software is not None:
 184         raise ValueError(f"software[]='{type(software)}' is not of type 'str'")
 185     elif software == "":
 186         raise ValueError("Parameter 'software' is empty")
 187     elif origin is not None and not validators.domain(origin.split("/")[0]):
 188         raise ValueError(f"Bad origin name='{origin}'")
 189     elif blacklist.is_blacklisted(domain):
 190         raise Exception(f"domain='{domain}' is blacklisted, but function invoked")
 191     elif domain.find("/profile/") > 0 or domain.find("/users/") > 0 or (is_registered(domain.split("/")[0]) and domain.find("/c/") > 0):
 192         raise Exception(f"domain='{domain}' is a single user")
 193     elif domain.find("/tag/") > 0:
 194         raise Exception(f"domain='{domain}' is a tag")
 195
 196     if software is None:
 197         try:
 198             logger.debug("domain='%s',origin='%s',command='%s',path='%s'", domain, origin, command, path)
 199             software = federation.determine_software(domain, path)
 200         except network.exceptions as exception:
 201             logger.warning("Exception '%s' during determining software type, domain='%s'", type(exception), domain)
 202             set_last_error(domain, exception)
 203
 204     logger.debug("Determined software='%s'", software)
 205     if software == "lemmy" and domain.find("/c/") > 0:
 206         domain = domain.split("/c/")[0]
 207
 208         logger.debug("domain='%s' - LEMMY /c/ !", domain)
 209         if is_registered(domain):
 210             logger.warning("domain='%s' already registered after cutting off user part. - EXIT!", domain)
 211             return
 212
 213     logger.info("Adding instance domain='%s',origin='%s',software='%s',command='%s'", domain, origin, software, command)
 214     database.cursor.execute(
 215         "INSERT INTO instances (domain, origin, command, hash, software, first_seen) VALUES (?, ?, ?, ?, ?, ?)",
 216         (
 217            domain,
 218            origin,
 219            command,
 220            utils.get_hash(domain),
 221            software,
 222            time.time()
 223         ),
 224     )
 225
 226     logger.debug("Marking domain='%s' as registered.", domain)
 227     cache.set_sub_key("is_registered", domain, True)
 228
 229     logger.debug("Checking if domain='%s' has pending updates ...", domain)
 230     if has_pending(domain):
 231         logger.debug("Flushing updates for domain='%s' ...", domain)
 232         update(domain)
 233
 234     logger.debug("EXIT!")
 235
 236 def set_last_nodeinfo(domain: str):
 237     logger.debug("domain='%s' - CALLED!", domain)
 238     domain_helper.raise_on(domain)
 239
 240     logger.debug("Updating last_nodeinfo for domain='%s'", domain)
 241     _set_data("last_nodeinfo", domain, time.time())
 242
 243     logger.debug("EXIT!")
 244
 245 def set_last_error(domain: str, error: dict):
 246     logger.debug("domain='%s',error[]='%s' - CALLED!", domain, type(error))
 247     domain_helper.raise_on(domain)
 248
 249     logger.debug("error[]='%s' - BEFORE!", type(error))
 250     if isinstance(error, (BaseException, json.decoder.JSONDecodeError)):
 251         error = f"error[{type(error)}]='{str(error)}'"
 252     logger.debug("error[]='%s' - AFTER!", type(error))
 253
 254     if isinstance(error, str):
 255         logger.debug("Setting last_error_details='%s' (str)", error)
 256         _set_data("last_status_code"  , domain, 999)
 257         _set_data("last_error_details", domain, error if error != "" else None)
 258     elif isinstance(error, requests.models.Response):
 259         logger.debug("Setting last_error_details='%s' (Response)", error.reason)
 260         _set_data("last_status_code"  , domain, error.status_code)
 261         _set_data("last_error_details", domain, error.reason if error.reason != "" else None)
 262     elif not isinstance(error, dict):
 263         raise KeyError(f"Cannot handle keys in error[{type(error)}]='{error}'")
 264     elif "status_code" in error and "error_message" in error:
 265         logger.debug("Setting last_error_details='%s' (error_message)", error['error_message'])
 266         _set_data("last_status_code"  , domain, error["status_code"])
 267         _set_data("last_error_details", domain, error["error_message"] if error["error_message"] != "" else None)
 268     elif "json" in error and "error" in error["json"] and "message" in error["json"]["error"]:
 269         logger.debug("Setting last_error_details='%s' (json,error)", error["json"]["error"]["message"])
 270         _set_data("last_status_code"  , domain, error["status_code"])
 271         _set_data("last_error_details", domain, error["json"]["error"]["message"] if error["json"]["error"]["message"] != "" else None)
 272     elif "json" in error and "error" in error["json"]:
 273         logger.debug("Setting last_error_details='%s' (json,error)", error["json"]["error"])
 274         _set_data("last_status_code"  , domain, error["status_code"])
 275         _set_data("last_error_details", domain, error["json"]["error"] if error["json"]["error"] != "" else None)
 276
 277     logger.debug("Invoking error_log.add(domain='%s',error[]='%s'", domain, type(error))
 278     error_log.add(domain, error)
 279
 280     logger.debug("EXIT!")
 281
 282 def set_success(domain: str):
 283     logger.debug("domain='%s' - CALLED!", domain)
 284     domain_helper.raise_on(domain)
 285
 286     # Set both to success
 287     _set_data("last_status_code"  , domain, 200)
 288     _set_data("last_error_details", domain, None)
 289
 290     logger.debug("EXIT!")
 291
 292 def is_registered(domain: str, skip_raise = False) -> bool:
 293     logger.debug("domain='%s',skip_raise='%s' - CALLED!", domain, skip_raise)
 294     domain_helper.raise_on(domain)
 295
 296     if not isinstance(skip_raise, bool):
 297         raise ValueError(f"skip_raise[]='{type(skip_raise)}' is not type of 'bool'")
 298
 299     if not skip_raise:
 300         domain_helper.raise_on(domain)
 301
 302     logger.debug("domain='%s' - CALLED!", domain)
 303     if not cache.key_exists("is_registered"):
 304         logger.debug("Cache for 'is_registered' not initialized, fetching all rows ...")
 305         database.cursor.execute("SELECT domain FROM instances")
 306
 307         # Check Set all
 308         cache.set_all("is_registered", database.cursor.fetchall(), True)
 309
 310     # Is cache found?
 311     registered = cache.sub_key_exists("is_registered", domain)
 312
 313     logger.debug("registered='%s' - EXIT!", registered)
 314     return registered
 315
 316 def is_recent(domain: str, column: str = "last_instance_fetch") -> bool:
 317     logger.debug("domain='%s',column='%s' - CALLED!", domain, column)
 318     domain_helper.raise_on(domain)
 319
 320     if not isinstance(column, str):
 321         raise ValueError(f"Parameter column[]='{type(column)}' is not of type 'str'")
 322     elif not column.startswith("last_"):
 323         raise ValueError(f"Parameter column='{column}' is not expected")
 324     elif not is_registered(domain):
 325         logger.debug("domain='%s' is not registered, returning False - EXIT!", domain)
 326         return False
 327
 328     key = "recheck_instance"
 329     if column == "last_blocked":
 330         key = "recheck_block"
 331
 332     # Query database
 333     database.cursor.execute(f"SELECT {column} FROM instances WHERE domain = ? LIMIT 1", [domain])
 334
 335     # Fetch row
 336     row = database.cursor.fetchone()
 337
 338     fetched = float(row[column]) if row[column] is not None else 0.0
 339
 340     diff = (time.time() - fetched)
 341
 342     logger.debug("fetched[%s]='%s',key='%s',diff=%f", type(fetched), fetched, key, diff)
 343     recently = bool(diff < config.get(key))
 344
 345     logger.debug("recently='%s' - EXIT!", recently)
 346     return recently
 347
 348 def deobfuscate(char: str, domain: str, blocked_hash: str = None) -> tuple:
 349     logger.debug("char='%s',domain='%s',blocked_hash='%s' - CALLED!", char, domain, blocked_hash)
 350
 351     if not isinstance(char, str):
 352         raise ValueError(f"Parameter char[]='{type(char)}' is not of type 'str'")
 353     elif char == "":
 354         raise ValueError("Parameter 'char' is empty")
 355     elif not char in domain:
 356         raise ValueError(f"char='{char}' not found in domain='{domain}' but function invoked")
 357     elif not isinstance(domain, str):
 358         raise ValueError(f"Parameter domain[]='{type(domain)}'")
 359     elif not isinstance(blocked_hash, str) and blocked_hash is not None:
 360         raise ValueError(f"Parameter blocked_hash[]='{type(blocked_hash)}' is not of type 'str'")
 361
 362     # Init row
 363     row = None
 364
 365     logger.debug("blocked_hash[]='%s'", type(blocked_hash))
 366     if isinstance(blocked_hash, str):
 367         logger.debug("Looking up blocked_hash='%s',domain='%s' ...", blocked_hash, domain)
 368         database.cursor.execute(
 369             "SELECT domain, origin, nodeinfo_url FROM instances WHERE hash = ? OR domain LIKE ? LIMIT 1", [blocked_hash, domain.replace(char, "_")]
 370         )
 371
 372         row = database.cursor.fetchone()
 373         logger.debug("row[]='%s'", type(row))
 374
 375         if row is None:
 376             logger.debug("blocked_hash='%s' not found, trying domain='%s' ...", blocked_hash, domain)
 377             return deobfuscate(char, domain)
 378     elif not domain.startswith("*."):
 379         logger.debug("domain='%s' - BEFORE!", domain)
 380         domain = tidyup.domain(domain)
 381         logger.debug("domain='%s' - AFTER!", domain)
 382
 383         if domain == "":
 384             logger.warning("domain is empty after tidyup - EXIT!")
 385             return None
 386
 387         search = domain.replace(char, "_")
 388
 389         logger.debug("Looking up domain='%s',search='%s' ...", domain, search)
 390         database.cursor.execute(
 391             "SELECT domain, origin, nodeinfo_url FROM instances WHERE domain LIKE ? OR 'https://' || domain LIKE ? ORDER BY rowid LIMIT 1", [search, search]
 392         )
 393
 394         row = database.cursor.fetchone()
 395         logger.debug("row[]='%s'", type(row))
 396
 397     logger.debug("row[]='%s' - EXIT!", type(row))
 398     return row
 399
 400 def set_last_blocked(domain: str):
 401     logger.debug("domain='%s' - CALLED!", domain)
 402     domain_helper.raise_on(domain)
 403
 404     # Set timestamp
 405     _set_data("last_blocked", domain, time.time())
 406     logger.debug("EXIT!")
 407
 408 def set_last_instance_fetch(domain: str):
 409     logger.debug("domain='%s' - CALLED!", domain)
 410     domain_helper.raise_on(domain)
 411
 412     # Set timestamp
 413     _set_data("last_instance_fetch", domain, time.time())
 414     logger.debug("EXIT!")
 415
 416 def set_last_response_time(domain: str, response_time: float):
 417     logger.debug("domain='%s',response_time=%d - CALLED!", domain, response_time)
 418     domain_helper.raise_on(domain)
 419
 420     if not isinstance(response_time, float):
 421         raise ValueError(f"response_time[]='{type(response_time)}' is not of type 'float'")
 422     elif response_time < 0:
 423         raise ValueError(f"response_time={response_time} is below zero")
 424
 425     # Set timestamp
 426     _set_data("last_response_time", domain, response_time)
 427     logger.debug("EXIT!")
 428
 429 def set_total_peers(domain: str, peers: list):
 430     logger.debug("domain='%s',peers()=%d - CALLED!", domain, len(peers))
 431     domain_helper.raise_on(domain)
 432
 433     if not isinstance(peers, list):
 434         raise ValueError(f"Parameter peers[]='{type(peers)}' is not of type 'list'")
 435
 436     # Set timestamp
 437     _set_data("total_peers", domain, len(peers))
 438     logger.debug("EXIT!")
 439
 440 def set_total_blocks(domain: str, blocks: list):
 441     logger.debug("domain='%s',blocks()=%d - CALLED!", domain, len(blocks))
 442     domain_helper.raise_on(domain)
 443
 444     if not isinstance(blocks, list):
 445         raise ValueError(f"Parameter blocks[]='{type(blocks)}' is not of type 'list'")
 446
 447     # Set timestamp
 448     _set_data("total_blocks", domain, len(blocks))
 449     logger.debug("EXIT!")
 450
 451 def set_obfuscated_blocks(domain: str, obfuscated: int):
 452     logger.debug("domain='%s',obfuscated=%d - CALLED!", domain, obfuscated)
 453     domain_helper.raise_on(domain)
 454
 455     if not isinstance(obfuscated, int):
 456         raise ValueError(f"Parameter obfuscated[]='{type(obfuscated)}' is not of type 'int'")
 457     elif obfuscated < 0:
 458         raise ValueError(f"Parameter obfuscated={obfuscated} is not valid")
 459
 460     # Set timestamp
 461     _set_data("obfuscated_blocks", domain, obfuscated)
 462     logger.debug("EXIT!")
 463
 464 def set_nodeinfo_url(domain: str, url: str):
 465     logger.debug("domain='%s',url='%s' - CALLED!", domain, url)
 466     domain_helper.raise_on(domain)
 467
 468     if not isinstance(url, str) and url is not None:
 469         raise ValueError(f"Parameter url[]='{type(url)}' is not of type 'str'")
 470     elif url == "":
 471         raise ValueError("Parameter 'url' is empty")
 472
 473     # Set timestamp
 474     _set_data("nodeinfo_url", domain, url)
 475     logger.debug("EXIT!")
 476
 477 def set_detection_mode(domain: str, mode: str):
 478     logger.debug("domain='%s',mode='%s' - CALLED!", domain, mode)
 479     domain_helper.raise_on(domain)
 480
 481     if not isinstance(mode, str) and mode is not None:
 482         raise ValueError(f"Parameter mode[]='{type(mode)}' is not of type 'str'")
 483     elif mode == "":
 484         raise ValueError("Parameter 'mode' is empty")
 485
 486     # Set timestamp
 487     _set_data("detection_mode", domain, mode)
 488     logger.debug("EXIT!")
 489
 490 def set_has_obfuscation(domain: str, status: bool):
 491     logger.debug("domain='%s',status='%s' - CALLED!", domain, status)
 492     domain_helper.raise_on(domain)
 493
 494     if not isinstance(status, bool):
 495         raise ValueError(f"Parameter status[]='{type(status)}' is not of type 'bool'")
 496
 497     # Set timestamp
 498     _set_data("has_obfuscation", domain, status)
 499     logger.debug("EXIT!")
 500
 501 def set_software(domain: str, software: str):
 502     logger.debug("domain='%s',software='%s' - CALLED!", domain, software)
 503     domain_helper.raise_on(domain)
 504
 505     if not isinstance(software, str) and software is not None:
 506         raise ValueError(f"Parameter software[]='{type(software)}' is not of type 'str'")
 507     elif software == "":
 508         raise ValueError("Parameter 'software' is empty")
 509
 510     # Set timestamp
 511     _set_data("software", domain, software)
 512     logger.debug("EXIT!")
 513
 514 def valid(value: str, column: str) -> bool:
 515     logger.debug("value='%s' - CALLED!", value)
 516     if not isinstance(value, str):
 517         raise ValueError(f"Parameter value[]='{type(value)}' is not of type 'str'")
 518     elif value == "":
 519         raise ValueError("Parameter 'value' is empty")
 520     elif not isinstance(column, str):
 521         raise ValueError(f"Parameter column[]='{type(column)}' is not of type 'str'")
 522     elif column == "":
 523         raise ValueError("Parameter 'column' is empty")
 524
 525     # Query database
 526     database.cursor.execute(
 527         f"SELECT {column} FROM instances WHERE {column} = ? LIMIT 1", [value]
 528     )
 529
 530     is_valid = database.cursor.fetchone() is not None
 531
 532     logger.debug("is_valid='%s' - EXIT!", is_valid)
 533     return is_valid
 534
 535 def translate_idnas(rows: list, column: str):
 536     logger.debug("rows[]='%s' - CALLED!", type(rows))
 537
 538     if not isinstance(rows, list):
 539         raise ValueError("rows[]='{type(rows)}' is not of type 'list'")
 540     elif len(rows) == 0:
 541         raise ValueError("Parameter 'rows' is an empty list")
 542     elif not isinstance(column, str):
 543         raise ValueError(f"column='{type(column)}' is not of type 'str'")
 544     elif column == "":
 545         raise ValueError("Parameter 'column' is empty")
 546     elif column not in ["domain", "origin"]:
 547         raise ValueError(f"column='{column}' is not supported")
 548
 549     logger.info("Checking/converting %d domain names ...", len(rows))
 550     for row in rows:
 551         logger.debug("row[]='%s'", type(row))
 552
 553         translated = row[column].encode("idna").decode("utf-8")
 554         logger.debug("translated='%s',row[%s]='%s'", translated, column, row[column])
 555
 556         if translated != row[column]:
 557             logger.info("Translated row[%s]='%s' to '%s'", column, row[column], translated)
 558             if is_registered(translated, True):
 559                 logger.warning("Deleting row[%s]='%s' as translated='%s' already exist", column, row[column], translated)
 560                 database.cursor.execute(f"DELETE FROM instances WHERE {column} = ? LIMIT 1", [row[column]])
 561             else:
 562                 logger.debug("Updating row[%s]='%s' to translated='%s' ...", column, row[column], translated)
 563                 database.cursor.execute(f"UPDATE instances SET {column} = ? WHERE {column} = ? LIMIT 1", [translated, row[column]])
 564
 565             logger.debug("Invoking commit() ...")
 566             database.connection.commit()
 567
 568     logger.debug("EXIT!")