log all the things

lbrynet/lbrynet_daemon/LBRYDaemon.py

@@ -691,6 +691,7 @@ class LBRYDaemon(jsonrpc.JSONRPC):
                 )
                 try:
                     self.reflector_server_port = reactor.listenTCP(self.reflector_port, reflector_factory)
+                    log.info('Started reflector on port %s', self.reflector_port)
                 except error.CannotListenError as e:
                     log.exception("Couldn't bind reflector to port %d", self.reflector_port)
                     raise ValueError("{} lbrynet may already be running on your computer.".format(e))

lbrynet/lbrynet_daemon/LBRYDaemonControl.py

@@ -77,7 +77,7 @@ def start():
     log_support.configure_file_handler(lbrynet_log)
     log_support.configure_loggly_handler()
     if args.logtoconsole:
-        log_support.configure_console()
+        log_support.configure_console(level='DEBUG')
 
     try:
         JSONRPCProxy.from_url(API_CONNECTION_STRING).is_running()

lbrynet/lbrynet_daemon/LBRYPublisher.py

@@ -47,9 +47,9 @@ class Publisher(object):
         self.metadata = {}
 
     def start(self, name, file_path, bid, metadata):
-
+        log.info('Starting publish for %s', name)
         def _show_result():
-            log.info("Published %s --> lbry://%s txid: %s", self.file_name, self.publish_name, self.txid)
+            log.info("Success! Published %s --> lbry://%s txid: %s", self.file_name, self.publish_name, self.txid)
             return defer.succeed(self.txid)
 
         self.publish_name = name
@@ -99,10 +99,13 @@ class Publisher(object):
         return d
 
     def _create_sd_blob(self):
-        d = publish_sd_blob(self.lbry_file_manager.stream_info_manager, self.session.blob_manager,
+        log.debug('Creating stream descriptor blob')
+        d = publish_sd_blob(self.lbry_file_manager.stream_info_manager,
+                            self.session.blob_manager,
                             self.lbry_file.stream_hash)
 
         def set_sd_hash(sd_hash):
+            log.debug('stream descriptor hash: %s', sd_hash)
             if 'sources' not in self.metadata:
                 self.metadata['sources'] = {}
             self.metadata['sources']['lbry_sd_hash'] = sd_hash
@@ -111,23 +114,29 @@ class Publisher(object):
         return d
 
     def set_status(self):
+        log.debug('Setting status')
         d = self.lbry_file_manager.change_lbry_file_status(self.lbry_file, ManagedLBRYFileDownloader.STATUS_FINISHED)
         d.addCallback(lambda _: self.lbry_file.restore())
         return d
 
     def _claim_name(self):
-        self.metadata['content-type'] = mimetypes.guess_type(os.path.join(self.lbry_file.download_directory,
+        log.debug('Claiming name')
-                                                                          self.lbry_file.file_name))[0]
+        self._update_metadata()
-        self.metadata['ver'] = CURRENT_METADATA_VERSION
         m = Metadata(self.metadata)
 
         def set_tx_hash(txid):
+            log.debug('Name claimed using txid: %s', txid)
             self.txid = txid
 
         d = self.wallet.claim_name(self.publish_name, self.bid_amount, m)
         d.addCallback(set_tx_hash)
         return d
 
+    def _update_metadata(self):
+        filename = os.path.join(self.lbry_file.download_directory, self.lbry_file.file_name)
+        self.metadata['content-type'] = get_content_type(filename)
+        self.metadata['ver'] = CURRENT_METADATA_VERSION        
+
     def _show_publish_error(self, err):
         log.info(err.getTraceback())
         message = "An error occurred publishing %s to %s. Error: %s."
@@ -140,3 +149,7 @@ class Publisher(object):
         log.error(message, str(self.file_name), str(self.publish_name), err.getTraceback())
 
         return defer.fail(Exception("Publish failed"))
+
+
+def get_content_type(filename):
+    return mimetypes.guess_type(filename)[0]

lbrynet/reflector/client/client.py

@@ -82,6 +82,7 @@ class LBRYFileReflectorClient(Protocol):
         d.addErrback(lambda err: log.warning("An error occurred immediately: %s", err.getTraceback()))
 
     def dataReceived(self, data):
+        log.debug('Recieved %s', data)
         self.response_buff += data
         try:
             msg = self.parse_response(self.response_buff)
@@ -95,8 +96,10 @@ class LBRYFileReflectorClient(Protocol):
 
     def connectionLost(self, reason):
         if reason.check(error.ConnectionDone):
+            log.debug('Finished sending data via reflector')
             self.factory.finished_deferred.callback(True)
         else:
+            log.debug('reflector finished: %s', reason)
             self.factory.finished_deferred.callback(reason)
 
     #  IConsumer stuff
@@ -118,7 +121,7 @@ class LBRYFileReflectorClient(Protocol):
             reactor.callLater(0, self.producer.resumeProducing)
 
     def get_blobs_to_send(self, stream_info_manager, stream_hash):
-        log.info("Get blobs to send to reflector")
+        log.debug('Getting blobs from stream hash: %s', stream_hash)
         d = stream_info_manager.get_blobs_for_stream(stream_hash)
 
         def set_blobs(blob_hashes):
@@ -139,6 +142,7 @@ class LBRYFileReflectorClient(Protocol):
         return d
 
     def send_handshake(self):
+        log.debug('Sending handshake')
         self.write(json.dumps({'version': 0}))
 
     def parse_response(self, buff):
@@ -198,6 +202,7 @@ class LBRYFileReflectorClient(Protocol):
         if blob.is_validated():
             read_handle = blob.open_for_reading()
             if read_handle is not None:
+                log.debug('Getting ready to send %s', blob.blob_hash)
                 self.next_blob_to_send = blob
                 self.read_handle = read_handle
                 return None
@@ -206,6 +211,7 @@ class LBRYFileReflectorClient(Protocol):
     def send_blob_info(self):
         log.info("Send blob info for %s", self.next_blob_to_send.blob_hash)
         assert self.next_blob_to_send is not None, "need to have a next blob to send at this point"
+        log.debug('sending blob info')
         self.write(json.dumps({
             'blob_hash': self.next_blob_to_send.blob_hash,
             'blob_size': self.next_blob_to_send.length
@@ -214,10 +220,12 @@ class LBRYFileReflectorClient(Protocol):
     def send_next_request(self):
         if self.file_sender is not None:
             # send the blob
+            log.debug('Sending the blob')
             return self.start_transfer()
         elif self.blob_hashes_to_send:
             # open the next blob to send
             blob_hash = self.blob_hashes_to_send[0]
+            log.debug('No current blob, sending the next one: %s', blob_hash)
             self.blob_hashes_to_send = self.blob_hashes_to_send[1:]
             d = self.blob_manager.get_blob(blob_hash, True)
             d.addCallback(self.open_blob_for_reading)
@@ -226,7 +234,8 @@ class LBRYFileReflectorClient(Protocol):
             return d
         else:
             # close connection
-            self.transport.loseConnection()
+            log.debug('No more blob hashes, closing connection')
+            self.transport.closeConnection()
 
 
 class LBRYFileReflectorClientFactory(ClientFactory):
@@ -244,3 +253,19 @@ class LBRYFileReflectorClientFactory(ClientFactory):
         p.factory = self
         self.p = p
         return p
+
+    def startFactory(self):
+        log.debug('Starting reflector factory')
+        ClientFactory.startFactory(self)
+    
+    def startedConnecting(self, connector):
+        log.debug('Started connecting')
+
+    def clientConnectionLost(self, connector, reason):
+        """If we get disconnected, reconnect to server."""
+        connector.connect()
+
+    def clientConnectionFailed(self, connector, reason):
+        print("connection failed:", reason)
+        from twisted.internet import reactor
+        reactor.stop()

tests/functional/test_reflector.py

@@ -104,7 +104,7 @@ class TestReflector(unittest.TestCase):
         d.addCallback(lambda _: self.server_blob_manager.setup())
 
         def verify_equal(sd_info):
-            self.assertEqual(sd_info, mocks.create_stream_sd_file)
+            self.assertEqual(mocks.create_stream_sd_file, sd_info)
 
         def save_sd_blob_hash(sd_hash):
             self.expected_blobs.append((sd_hash, 923))
@@ -122,12 +122,6 @@ class TestReflector(unittest.TestCase):
             d.addCallback(lambda _: stream_hash)
             return d
 
-        def iv_generator():
-            iv = 0
-            while 1:
-                iv += 1
-                yield "%016d" % iv
-
         def create_stream():
             test_file = mocks.GenFile(5209343, b''.join([chr(i + 3) for i in xrange(0, 64, 6)]))
             d = LBRYFileCreator.create_lbry_file(
@@ -187,3 +181,10 @@ class TestReflector(unittest.TestCase):
         d.addCallback(verify_stream_descriptor_file)
         d.addCallback(upload_to_reflector)
         return d
+
+
+def iv_generator():
+    iv = 0
+    while True:
+        iv += 1
+        yield "%016d" % iv