Merge pull request #483 from lbryio/add-traceback

Add traceback to error in EncryptedFileManager

CHANGELOG.md

@@ -8,6 +8,9 @@ can and probably will change functionality and break backwards compatability
 at anytime.
 
 ## [Unreleased]
+### Fixed
+ * Add better logging to help track down [#478](https://github.com/lbryio/lbry/issues/478)
+
 
 ## [0.8.3rc3] - 2017-02-14
 
@@ -16,6 +19,7 @@ at anytime.
 ## [0.8.3rc1] - 2017-02-13
 ### Changed
  * make connection manager unit testeable
+
 ### Fixed
  * Change EWOULDBLOCK error in DHT to warning. #481
  * mark peers as down if it fails download protocol
@@ -32,7 +36,7 @@ at anytime.
  * Convert GetStream to inclineCallbacks
  * Change callback condition in GetStream to the first data blob completing
  * Add local and remote heights to blockchain status
- 
+
 ### Fixed
  * Fix recursion depth error upon failed blob
  * Call stopProducing in reflector client file_sender when uploading is done
@@ -44,12 +48,12 @@ at anytime.
  * Fix updating a claim where the stream doesn't change
  * Fix claim_abandon
 
-
 ## [0.8.1] - 2017-02-01
 ### Changed
  * reflect all the blobs in a stream
  * change command line flags so that the more common usage is the default
  * change daemon function signatures to include names arguments
+
 ### Fixed
  * disable verbose twisted logs
  * improved wallet balance calculations
@@ -61,6 +65,7 @@ at anytime.
  * improved command line user experience
  * integrate twisted logging with python logging
  * Updated READMEs
+
 ### Fixed
  * Fixed bug where ConnectionManager wasn't being stopped
  * Fixed: #343

lbrynet/lbryfilemanager/EncryptedFileDownloader.py

@@ -51,7 +51,7 @@ class ManagedEncryptedFileDownloader(EncryptedFileSaver):
         if sd_hash:
             self.sd_hash = sd_hash[0]
         else:
-            raise Exception("No sd hash for stream hash %s", self.stream_hash)
+            raise Exception("No sd hash for stream hash %s" % self.stream_hash)
         claim_metadata = yield self.wallet.get_claim_metadata_for_sd_hash(self.sd_hash)
         if claim_metadata is None:
             raise Exception("A claim doesn't exist for sd %s" % self.sd_hash)
@@ -59,7 +59,10 @@ class ManagedEncryptedFileDownloader(EncryptedFileSaver):
         self.claim_id = yield self.wallet.get_claimid(self.uri, self.txid, self.nout)
         status = yield self.lbry_file_manager.get_lbry_file_status(self)
         if status == ManagedEncryptedFileDownloader.STATUS_RUNNING:
-            yield self.start()
+            # start returns self.finished_deferred
+            # which fires when we've finished downloading the file
+            # and we don't want to wait for the entire download
+            self.start()
         elif status == ManagedEncryptedFileDownloader.STATUS_STOPPED:
             defer.returnValue(False)
         elif status == ManagedEncryptedFileDownloader.STATUS_FINISHED:
@@ -96,6 +99,7 @@ class ManagedEncryptedFileDownloader(EncryptedFileSaver):
 
     @defer.inlineCallbacks
     def _start(self):
+        log.info('Starting Downloader for %s', self.stream_hash)
         yield EncryptedFileSaver._start(self)
         sd_hash = yield self.stream_info_manager.get_sd_blob_hashes_for_stream(self.stream_hash)
         if len(sd_hash):
@@ -107,6 +111,7 @@ class ManagedEncryptedFileDownloader(EncryptedFileSaver):
                 self.txid = txid
                 self.nout = nout
         status = yield self._save_status()
+        log.info('Set Downloader status for %s to %s', self.stream_hash, status)
         defer.returnValue(status)
 
     def _get_finished_deferred_callback_value(self):

lbrynet/lbryfilemanager/EncryptedFileManager.py

@@ -43,7 +43,6 @@ class EncryptedFileManager(object):
         self.stream_info_manager = stream_info_manager
         self.sd_identifier = sd_identifier
         self.lbry_files = []
-        self.lbry_files_setup_deferred = None
         self.sql_db = None
         if download_directory:
             self.download_directory = download_directory
@@ -114,29 +113,27 @@ class EncryptedFileManager(object):
         yield defer.DeferredList(list(_iter_streams(stream_hashes)))
 
     @defer.inlineCallbacks
-    def _restore_lbry_file(self, lbry_file):
+    def _start_lbry_files(self):
-        try:
+        yield self._check_stream_info_manager()
-            yield lbry_file.restore()
+        files_and_options = yield self._get_all_lbry_files()
-        except Exception as err:
+        yield defer.DeferredList([
-            log.error("Failed to start stream: %s, error: %s", lbry_file.stream_hash, err)
+            self._set_options_and_restore(rowid, stream_hash, options)
-            self.lbry_files.remove(lbry_file)
+            for rowid, stream_hash, options in files_and_options
-            # TODO: delete stream without claim instead of just removing from manager?
+        ])
+        log.info("Started %i lbry files", len(self.lbry_files))
 
     @defer.inlineCallbacks
-    def _start_lbry_files(self):
+    def _set_options_and_restore(self, rowid, stream_hash, options):
-        b_prm = self.session.base_payment_rate_manager
+        try:
-        payment_rate_manager = NegotiatedPaymentRateManager(b_prm, self.session.blob_tracker)
+            b_prm = self.session.base_payment_rate_manager
-        yield self._check_stream_info_manager()
+            payment_rate_manager = NegotiatedPaymentRateManager(
-        lbry_files_and_options = yield self._get_all_lbry_files()
+                b_prm, self.session.blob_tracker)
-        dl = []
+            downloader = yield self.start_lbry_file(
-        for rowid, stream_hash, options in lbry_files_and_options:
+                rowid, stream_hash, payment_rate_manager, blob_data_rate=options)
-            lbry_file = yield self.start_lbry_file(rowid, stream_hash, payment_rate_manager,
+            yield downloader.restore()
-                                                   blob_data_rate=options)
+        except Exception:
-            dl.append(self._restore_lbry_file(lbry_file))
+            log.exception('An error occurred while starting a lbry file (%s, %s, %s)',
-            log.debug("Started %s", lbry_file)
+                          rowid, stream_hash, options)
-        self.lbry_files_setup_deferred = defer.DeferredList(dl)
-        log.info("Started %i lbry files", len(self.lbry_files))
-        defer.returnValue(True)
 
     @defer.inlineCallbacks
     def start_lbry_file(self, rowid, stream_hash,
@@ -145,16 +142,23 @@ class EncryptedFileManager(object):
         if not download_directory:
             download_directory = self.download_directory
         payment_rate_manager.min_blob_data_payment_rate = blob_data_rate
-        lbry_file = ManagedEncryptedFileDownloader(rowid, stream_hash, self.session.peer_finder,
+        lbry_file_downloader = ManagedEncryptedFileDownloader(
-                                                   self.session.rate_limiter,
+            rowid,
-                                                   self.session.blob_manager,
+            stream_hash,
-                                                   self.stream_info_manager,
+            self.session.peer_finder,
-                                                   self, payment_rate_manager, self.session.wallet,
+            self.session.rate_limiter,
-                                                   download_directory, upload_allowed,
+            self.session.blob_manager,
-                                                   file_name=file_name)
+            self.stream_info_manager,
-        yield lbry_file.set_stream_info()
+            self,
-        self.lbry_files.append(lbry_file)
+            payment_rate_manager,
-        defer.returnValue(lbry_file)
+            self.session.wallet,
+            download_directory,
+            upload_allowed,
+            file_name=file_name
+        )
+        yield lbry_file_downloader.set_stream_info()
+        self.lbry_files.append(lbry_file_downloader)
+        defer.returnValue(lbry_file_downloader)
 
     @defer.inlineCallbacks
     def _stop_lbry_file(self, lbry_file):

lbrynet/lbrynet_daemon/Daemon.py

@@ -649,18 +649,19 @@ class Daemon(AuthJSONRPCServer):
             session_id=self._session_id
         )
 
+    @defer.inlineCallbacks
     def _setup_lbry_file_manager(self):
+        log.info('Starting to setup up file manager')
         self.startup_status = STARTUP_STAGES[3]
-        d = self.stream_info_manager.setup()
+        yield self.stream_info_manager.setup()
-
+        self.lbry_file_manager = EncryptedFileManager(
-        def set_lbry_file_manager():
+            self.session,
-            self.lbry_file_manager = EncryptedFileManager(
+            self.stream_info_manager,
-                self.session, self.stream_info_manager,
+            self.sd_identifier,
-                self.sd_identifier, download_directory=self.download_directory)
+            download_directory=self.download_directory
-            return self.lbry_file_manager.setup()
+        )
-
+        yield self.lbry_file_manager.setup()
-        d.addCallback(lambda _: set_lbry_file_manager())
+        log.info('Done setting up file manager')
-        return d
 
     def _get_analytics(self):
         if not self.analytics_manager.is_started: