From 6bdb0280be0e8c3274d7b0b63a7132cc75c22caa Mon Sep 17 00:00:00 2001 From: jobevers Date: Sat, 11 Feb 2017 09:09:57 -0600 Subject: [PATCH 1/8] better log exception in EncryptedFileManager The error message in #478 is too generic. This wraps the source of the error in a try/catch and logs the traceback. --- .../lbryfilemanager/EncryptedFileManager.py | 37 +++++++++---------- 1 file changed, 18 insertions(+), 19 deletions(-) diff --git a/lbrynet/lbryfilemanager/EncryptedFileManager.py b/lbrynet/lbryfilemanager/EncryptedFileManager.py index 1fca82272..9fb7883d6 100644 --- a/lbrynet/lbryfilemanager/EncryptedFileManager.py +++ b/lbrynet/lbryfilemanager/EncryptedFileManager.py @@ -113,31 +113,30 @@ class EncryptedFileManager(object): log.debug("Checking %s streams", len(stream_hashes)) yield defer.DeferredList(list(_iter_streams(stream_hashes))) - @defer.inlineCallbacks - def _restore_lbry_file(self, lbry_file): - try: - yield lbry_file.restore() - except Exception as err: - log.error("Failed to start stream: %s, error: %s", lbry_file.stream_hash, err) - self.lbry_files.remove(lbry_file) - # TODO: delete stream without claim instead of just removing from manager? - @defer.inlineCallbacks def _start_lbry_files(self): - b_prm = self.session.base_payment_rate_manager - payment_rate_manager = NegotiatedPaymentRateManager(b_prm, self.session.blob_tracker) yield self._check_stream_info_manager() - lbry_files_and_options = yield self._get_all_lbry_files() - dl = [] - for rowid, stream_hash, options in lbry_files_and_options: - lbry_file = yield self.start_lbry_file(rowid, stream_hash, payment_rate_manager, - blob_data_rate=options) - dl.append(self._restore_lbry_file(lbry_file)) - log.debug("Started %s", lbry_file) - self.lbry_files_setup_deferred = defer.DeferredList(dl) + files_and_options = yield self._get_all_lbry_files() + yield defer.DeferredList([ + self._set_options_and_restore(rowid, stream_hash, options) + for rowid, stream_hash, options in files_and_options + ]) log.info("Started %i lbry files", len(self.lbry_files)) defer.returnValue(True) + @defer.inlineCallbacks + def _set_options_and_restore(self, rowid, stream_hash, options): + try: + b_prm = self.session.base_payment_rate_manager + payment_rate_manager = NegotiatedPaymentRateManager( + b_prm, self.session.blob_tracker) + downloader = yield self.start_lbry_file( + rowid, stream_hash, payment_rate_manager, blob_data_rate=options) + yield downloader.restore() + except Exception: + log.exception('An error occurred while starting a lbry file (%s, %s, %s)', + rowid, stream_hash, options) + @defer.inlineCallbacks def start_lbry_file(self, rowid, stream_hash, payment_rate_manager, blob_data_rate=None, upload_allowed=True, From 3bdd33567b57aa8b76d37d506369cff85e1ae706 Mon Sep 17 00:00:00 2001 From: jobevers Date: Sat, 11 Feb 2017 09:12:21 -0600 Subject: [PATCH 2/8] whitespace --- .../lbryfilemanager/EncryptedFileManager.py | 27 ++++++++++++------- 1 file changed, 17 insertions(+), 10 deletions(-) diff --git a/lbrynet/lbryfilemanager/EncryptedFileManager.py b/lbrynet/lbryfilemanager/EncryptedFileManager.py index 9fb7883d6..84a6626d0 100644 --- a/lbrynet/lbryfilemanager/EncryptedFileManager.py +++ b/lbrynet/lbryfilemanager/EncryptedFileManager.py @@ -144,16 +144,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, - self.session.rate_limiter, - self.session.blob_manager, - self.stream_info_manager, - self, payment_rate_manager, self.session.wallet, - download_directory, upload_allowed, - file_name=file_name) - yield lbry_file.set_stream_info() - self.lbry_files.append(lbry_file) - defer.returnValue(lbry_file) + lbry_file_downloader = ManagedEncryptedFileDownloader( + rowid, + stream_hash, + self.session.peer_finder, + self.session.rate_limiter, + self.session.blob_manager, + self.stream_info_manager, + self, + payment_rate_manager, + 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): From a43b726f32cb17ac880daed8477faeceb1192e1a Mon Sep 17 00:00:00 2001 From: jobevers Date: Sat, 11 Feb 2017 09:13:45 -0600 Subject: [PATCH 3/8] update changelog --- CHANGELOG.md | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3e9babee4..eade334dc 100644 --- a/CHANGELOG.md +++ b/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 From 62fcbc23e358fd4d81b6f52da9b8dd236464e70f Mon Sep 17 00:00:00 2001 From: jobevers Date: Tue, 14 Feb 2017 10:25:03 -0600 Subject: [PATCH 4/8] bugfix: exception needs string interpolation --- lbrynet/lbryfilemanager/EncryptedFileDownloader.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lbrynet/lbryfilemanager/EncryptedFileDownloader.py b/lbrynet/lbryfilemanager/EncryptedFileDownloader.py index 5b69d982d..aae2a2e03 100644 --- a/lbrynet/lbryfilemanager/EncryptedFileDownloader.py +++ b/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) From ffb48ef287c9a49a51ac40065c61264cf05540ee Mon Sep 17 00:00:00 2001 From: jobevers Date: Tue, 14 Feb 2017 10:25:34 -0600 Subject: [PATCH 5/8] bugfix: on restore, dont wait for download to finish --- lbrynet/lbryfilemanager/EncryptedFileDownloader.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/lbrynet/lbryfilemanager/EncryptedFileDownloader.py b/lbrynet/lbryfilemanager/EncryptedFileDownloader.py index aae2a2e03..170bc6714 100644 --- a/lbrynet/lbryfilemanager/EncryptedFileDownloader.py +++ b/lbrynet/lbryfilemanager/EncryptedFileDownloader.py @@ -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: From 993d606bc69eef1ef821b121b96cf4076d73b4f4 Mon Sep 17 00:00:00 2001 From: jobevers Date: Tue, 14 Feb 2017 10:26:03 -0600 Subject: [PATCH 6/8] add logging on downloader start --- lbrynet/lbryfilemanager/EncryptedFileDownloader.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/lbrynet/lbryfilemanager/EncryptedFileDownloader.py b/lbrynet/lbryfilemanager/EncryptedFileDownloader.py index 170bc6714..e1035df31 100644 --- a/lbrynet/lbryfilemanager/EncryptedFileDownloader.py +++ b/lbrynet/lbryfilemanager/EncryptedFileDownloader.py @@ -99,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): @@ -110,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): From dbb6c6f3a40473eac20b7d5ffd6add7238753be6 Mon Sep 17 00:00:00 2001 From: jobevers Date: Tue, 14 Feb 2017 10:26:45 -0600 Subject: [PATCH 7/8] remove unused parts of file manager --- lbrynet/lbryfilemanager/EncryptedFileManager.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/lbrynet/lbryfilemanager/EncryptedFileManager.py b/lbrynet/lbryfilemanager/EncryptedFileManager.py index 84a6626d0..b4ad6b7c4 100644 --- a/lbrynet/lbryfilemanager/EncryptedFileManager.py +++ b/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 @@ -122,7 +121,6 @@ class EncryptedFileManager(object): for rowid, stream_hash, options in files_and_options ]) log.info("Started %i lbry files", len(self.lbry_files)) - defer.returnValue(True) @defer.inlineCallbacks def _set_options_and_restore(self, rowid, stream_hash, options): From 520ac9b50aced69063eae6580ac8840971c4a75b Mon Sep 17 00:00:00 2001 From: jobevers Date: Tue, 14 Feb 2017 10:27:16 -0600 Subject: [PATCH 8/8] change filemanger setup to inlinecallbacks --- lbrynet/lbrynet_daemon/Daemon.py | 21 +++++++++++---------- 1 file changed, 11 insertions(+), 10 deletions(-) diff --git a/lbrynet/lbrynet_daemon/Daemon.py b/lbrynet/lbrynet_daemon/Daemon.py index 8b54148ba..fc1a34e58 100644 --- a/lbrynet/lbrynet_daemon/Daemon.py +++ b/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() - - def set_lbry_file_manager(): - self.lbry_file_manager = EncryptedFileManager( - self.session, self.stream_info_manager, - self.sd_identifier, download_directory=self.download_directory) - return self.lbry_file_manager.setup() - - d.addCallback(lambda _: set_lbry_file_manager()) - return d + yield self.stream_info_manager.setup() + self.lbry_file_manager = EncryptedFileManager( + self.session, + self.stream_info_manager, + self.sd_identifier, + download_directory=self.download_directory + ) + yield self.lbry_file_manager.setup() + log.info('Done setting up file manager') def _get_analytics(self): if not self.analytics_manager.is_started: