add logging to some scheduling and syncing code

anki/cards.py

@@ -1,6 +1,7 @@
 # -*- coding: utf-8 -*-
 # Copyright: Damien Elmes <anki@ichi2.net>
 # License: GNU AGPL, version 3 or later; http://www.gnu.org/licenses/agpl.html
+import pprint
 
 import time
 from anki.utils import intTime, timestampID, joinFields
@@ -106,6 +107,7 @@ insert or replace into cards values
             self.odid,
             self.flags,
             self.data)
+        self.col.log(self)
 
     def flushSched(self):
         self.mod = intTime()
@@ -121,6 +123,7 @@ lapses=?, left=?, odue=?, odid=?, did=? where id = ?""",
             self.mod, self.usn, self.type, self.queue, self.due, self.ivl,
             self.factor, self.reps, self.lapses,
             self.left, self.odue, self.odid, self.did, self.id)
+        self.col.log(self)
 
     def q(self, reload=False, browser=False):
         return self.css() + self._getQA(reload, browser)['q']
@@ -180,3 +183,12 @@ lapses=?, left=?, odue=?, odid=?, did=? where id = ?""",
             self.model(), joinFields(self.note().fields))
         if self.ord not in ords:
             return True
+
+    def __repr__(self):
+        d = dict(self.__dict__)
+        # remove non-useful elements
+        del d['_note']
+        del d['_qa']
+        del d['col']
+        del d['timerStarted']
+        return pprint.pformat(d, width=300)

anki/collection.py

@@ -51,6 +51,7 @@ class _Collection(object):
     def __init__(self, db, server=False):
         self.db = db
         self.path = db._path
+        self.log(self.path, anki.version)
         self.server = server
         self._lastSave = time.time()
         self.clearUndo()
@@ -205,7 +206,9 @@ crt=?, mod=?, scm=?, dty=?, usn=?, ls=?, conf=?""",
     ##########################################################################
 
     def getCard(self, id):
-        return anki.cards.Card(self, id)
+        c = anki.cards.Card(self, id)
+        self.log(c)
+        return c
 
     def getNote(self, id):
         return anki.notes.Note(self, id=id)
@@ -767,3 +770,9 @@ and queue = 0""", intTime(), self.usn())
         self.db.execute("vacuum")
         self.db.execute("analyze")
         self.lock()
+
+    # Logging
+    ##########################################################################
+
+    def log(self, *args):
+        runHook("log", args)

anki/sched.py

@@ -55,6 +55,7 @@ class Scheduler(object):
         self._haveQueues = True
 
     def answerCard(self, card, ease):
+        self.col.log()
         assert ease >= 1 and ease <= 4
         self.col.markReview(card)
         if self._burySiblingsOnAnswer:
@@ -142,14 +143,20 @@ order by due""" % self._deckLimit(),
     def unburyCards(self):
         "Unbury cards."
         self.col.conf['lastUnburied'] = self.today
+        self.col.log(
+            self.col.db.list("select id from cards where queue = -2"))
         self.col.db.execute(
             "update cards set mod=?,usn=?,queue=type where queue = -2",
             intTime(), self.col.usn())
 
     def unburyCardsForDeck(self):
+        sids = ids2str(self.col.decks.active())
+        self.col.log(
+            self.col.db.list("select id from cards where queue = -2 and did in %s"
+                             % sids))
         self.col.db.execute(
             "update cards set mod=?,usn=?,queue=type where queue = -2 and did in %s"
-            % ids2str(self.col.decks.active()), intTime(), self.col.usn())
+            % sids, intTime(), self.col.usn())
 
     # Rev/lrn/time daily stats
     ##########################################################################
@@ -946,12 +953,14 @@ select id from cards where did in %s and queue = 2 and due <= ? limit ?)"""
             ids = []
             return ids
         # move the cards over
+        self.col.log(deck['id'], ids)
         self._moveToDyn(deck['id'], ids)
         return ids
 
     def emptyDyn(self, did, lim=None):
         if not lim:
             lim = "did = %s" % did
+        self.col.log(self.col.db.list("select id from cards where %s" % lim))
         # move out of cram queue
         self.col.db.execute("""
 update cards set did = odid, queue = (case when type = 1 then 0
@@ -1242,6 +1251,7 @@ To study outside of the normal schedule, click the Custom Study button below."""
 
     def suspendCards(self, ids):
         "Suspend cards."
+        self.col.log(ids)
         self.remFromDyn(ids)
         self.removeLrn(ids)
         self.col.db.execute(
@@ -1250,6 +1260,7 @@ To study outside of the normal schedule, click the Custom Study button below."""
 
     def unsuspendCards(self, ids):
         "Unsuspend cards."
+        self.col.log(ids)
         self.col.db.execute(
             "update cards set queue=type,mod=?,usn=? "
             "where queue = -1 and id in "+ ids2str(ids),
@@ -1259,6 +1270,7 @@ To study outside of the normal schedule, click the Custom Study button below."""
         "Bury all cards for note until next session."
         cids = self.col.db.list(
             "select id from cards where nid = ? and queue >= 0", nid)
+        self.col.log(cids)
         self.removeLrn(cids)
         self.col.db.execute("""
 update cards set queue=-2,mod=?,usn=? where id in """+ids2str(cids),
@@ -1295,9 +1307,11 @@ and (queue=0 or (queue=2 and due<=?))""",
                 except ValueError:
                     pass
         # then bury
-        self.col.db.execute(
+        if toBury:
-            "update cards set queue=-2,mod=?,usn=? where id in "+ids2str(toBury),
+            self.col.db.execute(
-            intTime(), self.col.usn())
+                "update cards set queue=-2,mod=?,usn=? where id in "+ids2str(toBury),
+                intTime(), self.col.usn())
+            self.col.log(toBury)
 
     # Resetting
     ##########################################################################
@@ -1311,6 +1325,7 @@ and (queue=0 or (queue=2 and due<=?))""",
             "select max(due) from cards where type=0") or 0
         # takes care of mod + usn
         self.sortCards(ids, start=pmax+1)
+        self.col.log(ids)
 
     def reschedCards(self, ids, imin, imax):
         "Put cards in review queue with a new interval in days (min, max)."
@@ -1326,6 +1341,7 @@ and (queue=0 or (queue=2 and due<=?))""",
 update cards set type=2,queue=2,ivl=:ivl,due=:due,
 usn=:usn, mod=:mod, factor=:fact where id=:id and odid=0 and queue >=0""",
                                 d)
+        self.col.log(ids)
 
     def resetCards(self, ids):
         "Completely reset cards for export."
@@ -1335,6 +1351,7 @@ usn=:usn, mod=:mod, factor=:fact where id=:id and odid=0 and queue >=0""",
         self.col.db.execute(
             "update cards set reps=0, lapses=0 where id in " + ids2str(nonNew))
         self.forgetCards(nonNew)
+        self.col.log(ids)
 
     # Repositioning new cards
     ##########################################################################
@@ -1377,6 +1394,7 @@ and due >= ? and queue = 0""" % scids, now, self.col.usn(), shiftby, low)
             d.append(dict(now=now, due=due[nid], usn=self.col.usn(), cid=id))
         self.col.db.executemany(
             "update cards set due=:due,mod=:now,usn=:usn where id = :cid", d)
+        self.col.log(cids)
 
     def randomizeCards(self, did):
         cids = self.col.db.list("select id from cards where did = ?", did)

anki/sync.py

@@ -105,6 +105,7 @@ class Syncer(object):
         # step 1: login & metadata
         runHook("sync", "login")
         meta = self.server.meta()
+        self.col.log("rmeta", meta)
         if not meta:
             return "badAuth"
         rscm = meta['scm']
@@ -125,19 +126,24 @@ class Syncer(object):
             # and require confirmation if it's non-empty
             pass
         meta = self.meta()
+        self.col.log("lmeta", meta)
         self.lmod = meta['mod']
         self.minUsn = meta['usn']
         lscm = meta['scm']
         lts = meta['ts']
         if abs(rts - lts) > 300:
+            self.col.log("clock off")
             return "clockOff"
         if self.lmod == self.rmod:
+            self.col.log("no changes")
             return "noChanges"
         elif lscm != rscm:
+            self.col.log("schema diff")
             return "fullSync"
         self.lnewer = self.lmod > self.rmod
         # step 1.5: check collection is valid
         if not self.col.basicCheck():
+            self.col.log("basic check")
             return "basicCheckFailed"
         # step 2: deletions
         runHook("sync", "meta")
@@ -154,6 +160,7 @@ class Syncer(object):
         while 1:
             runHook("sync", "stream")
             chunk = self.server.chunk()
+            self.col.log("server chunk", chunk)
             self.applyChunk(chunk=chunk)
             if chunk['done']:
                 break
@@ -162,6 +169,7 @@ class Syncer(object):
         while 1:
             runHook("sync", "stream")
             chunk = self.chunk()
+            self.col.log("client chunk", chunk)
             self.server.applyChunk(chunk=chunk)
             if chunk['done']:
                 break
@@ -478,6 +486,7 @@ from notes where %s""" % d)
         for r in data:
             if r[0] not in lmods or lmods[r[0]] < r[modIdx]:
                 update.append(r)
+        self.col.log(table, data)
         return update
 
     def mergeCards(self, cards):

aqt/main.py

@@ -3,6 +3,7 @@
 # License: GNU AGPL, version 3 or later; http://www.gnu.org/licenses/agpl.html
 
 import os
+import pprint
 import sys
 import re
 import traceback
@@ -269,7 +270,8 @@ To import into a password protected profile, please open the profile before atte
             showWarning("""\
 Your collection is corrupt. Please see the manual for \
 how to restore from a backup.""")
-            return self.unloadProfile()
+            self.unloadProfile()
+            raise
         self.hideSchemaMsg = False
         self.progress.setupDB(self.col.db)
         self.maybeEnableUndo()
@@ -837,6 +839,7 @@ the problem and restart Anki.""")
     def setupHooks(self):
         addHook("modSchema", self.onSchemaMod)
         addHook("remNotes", self.onRemNotes)
+        addHook("log", self.onLog)
 
     # Log note deletion
     ##########################################################################
@@ -854,6 +857,22 @@ the problem and restart Anki.""")
                 f.write(("\t".join([str(id), str(mid)] + fields)).encode("utf8"))
                 f.write("\n")
 
+    # Debug logging
+    ##########################################################################
+
+    def onLog(self, args):
+        def customRepr(x):
+            if isinstance(x, basestring):
+                return x
+            return pprint.pformat(x)
+        path, num, fn, y = traceback.extract_stack(limit=4)[0]
+        buf = "[%s] %s:%s(): %s" % (intTime(), os.path.basename(path), fn,
+            ", ".join([customRepr(x) for x in args]))
+        lpath = re.sub("\.anki2$", ".log", self.pm.collectionPath())
+        open(lpath, "ab").write(buf + "\n")
+        if os.environ.get("LOG"):
+            print buf
+
     # Schema modifications
     ##########################################################################