[Checkins] SVN: relstorage/trunk/relstorage/ Fixed some bugs in the recent zodbconvert changes:

[Shane Hathaway]

Log message for revision 119953:
  Fixed some bugs in the recent zodbconvert changes:
  
  - The changes broke the ability to convert from RelStorage to something
    else.  The existing tests revealed this.  Please run the tests before
    committing.
  
  - There was a potential for division by zero when producing log messages,
    especially on Windows, where time.time() is more granular.
  
  - There was a potential for a NameError if the source storage had
    no transactions.
  
  - Counting the list of source transactions could take a long time,
    so log before counting.
  

Changed:
  U   relstorage/trunk/relstorage/storage.py
  U   relstorage/trunk/relstorage/zodbconvert.py

-=-
Modified: relstorage/trunk/relstorage/storage.py
===================================================================
--- relstorage/trunk/relstorage/storage.py	2011-01-26 21:41:18 UTC (rev 119952)
+++ relstorage/trunk/relstorage/storage.py	2011-01-26 22:23:34 UTC (rev 119953)
@@ -1310,11 +1310,15 @@
         # adapted from ZODB.blob.BlobStorageMixin
         begin_time = time.time()
         txnum = 0
-        tx_size = 0
+        total_size = 0
+        log.info("Counting the transactions to copy.")
         num_txns = len(list(other.iterator()))
+        log.info("Copying the transactions.")
         for trans in other.iterator():
+            txnum += 1
+            num_txn_records = 0
+
             self.tpc_begin(trans, trans.tid, trans.status)
-            num_txn_records = 0
             for record in trans:
                 blobfilename = None
                 if self.blobhelper is not None:
@@ -1336,28 +1340,27 @@
                     self.restore(record.oid, record.tid, record.data,
                                  '', record.data_txn, trans)
                 num_txn_records += 1
-                try:
-                    tx_size += len(record.data)
-                except TypeError:
-                    # data is probably None
-                    pass
-            txnum += 1
-            tx_end = time.time()
-            pct_complete = (txnum / float(num_txns)) * 100
-            if pct_complete < 10:
-                pct_complete = '  %1.2f%%' % pct_complete
-            elif pct_complete < 100:
-                pct_complete = ' %1.2f%%' % pct_complete
-            rate = (tx_size / 1e6) / (tx_end - begin_time)
-
+                if record.data:
+                    total_size += len(record.data)
             self.tpc_vote(trans)
             self.tpc_finish(trans)
-            log.info("Restored tid %d,%5d records | %1.3f MB/s (%6d/%6d,%s)",
-                     u64(trans.tid), num_txn_records, rate, txnum, num_txns,
-                     pct_complete)
 
-        return txnum, tx_size, tx_end - begin_time
+            pct_complete = '%1.2f%%' % (txnum * 100.0 / num_txns)
+            elapsed = time.time() - begin_time
+            if elapsed:
+                rate = total_size / 1e6 / elapsed
+            else:
+                rate = 0.0
+            rate_str = '%1.3f' % rate
+            log.info("Copied tid %d,%5d records | %6s MB/s (%6d/%6d,%7s)",
+                     u64(trans.tid), num_txn_records, rate_str,
+                     txnum, num_txns, pct_complete)
 
+        elapsed = time.time() - begin_time
+        log.info(
+            "All %d transactions copied successfully in %4.1f minutes.",
+            txnum, elapsed / 60.0)
+
     # The propagate_invalidations flag implements the old
     # invalidation polling API and is not otherwise used. Set to a
     # false value, it tells the Connection not to propagate object

Modified: relstorage/trunk/relstorage/zodbconvert.py
===================================================================
--- relstorage/trunk/relstorage/zodbconvert.py	2011-01-26 21:41:18 UTC (rev 119952)
+++ relstorage/trunk/relstorage/zodbconvert.py	2011-01-26 22:23:34 UTC (rev 119953)
@@ -36,9 +36,6 @@
 """
 
 log = logging.getLogger("relstorage.zodbconvert")
-logging.basicConfig(
-    level=logging.INFO,
-    format="%(asctime)s %(levelname)s:%(name)s: %(message)s")
 
 
 def storage_has_data(storage):
@@ -70,6 +67,10 @@
     if len(args) != 1:
         parser.error("The name of one configuration file is required.")
 
+    logging.basicConfig(
+        level=logging.INFO,
+        format="%(asctime)s [%(name)s] %(levelname)s %(message)s")
+
     schema = ZConfig.loadSchemaFile(StringIO(schema_xml))
     config, handler = ZConfig.loadConfig(schema, args[0])
     source = config.source.open()
@@ -103,19 +104,10 @@
             msg = "Error: the destination storage has data.  Try --clear."
             sys.exit(msg)
 
-        log.info("Started copying transactions...")
-        log.info("This will take long...")
-        num_txns, size, elapsed = destination.copyTransactionsFrom(source)
-        log.info("Done copying transactions.")
-        log.info("Closing up...")
-
+        destination.copyTransactionsFrom(source)
         source.close()
         destination.close()
 
-        rate = (size / 1e6) / elapsed
-        log.info("All %d transactions copied successfully in %4.1f minutes "
-                 "at %1.3f MB/s.", num_txns, elapsed / 60, rate)
 
-
 if __name__ == '__main__':
     main()