From 5c27b9eb90179400a5375a963c0a86ea93f8db14 Mon Sep 17 00:00:00 2001 From: Job Evers-Meltzer Date: Sat, 16 Jul 2016 01:15:58 -0500 Subject: [PATCH] use asctime in logging format Instead of manually adding datetime.now() use asctime formatter to do it for us. --- lbrynet/lbrynet_daemon/LBRYDaemon.py | 53 +++++++++++---------- lbrynet/lbrynet_daemon/LBRYDaemonControl.py | 16 ++++++- lbrynet/lbrynet_daemon/LBRYDaemonServer.py | 10 ++-- lbrynet/lbrynet_daemon/LBRYDownloader.py | 2 +- lbrynet/lbrynet_daemon/LBRYPublisher.py | 4 +- 5 files changed, 50 insertions(+), 35 deletions(-) diff --git a/lbrynet/lbrynet_daemon/LBRYDaemon.py b/lbrynet/lbrynet_daemon/LBRYDaemon.py index ceb8a87a7..888406e09 100644 --- a/lbrynet/lbrynet_daemon/LBRYDaemon.py +++ b/lbrynet/lbrynet_daemon/LBRYDaemon.py @@ -66,6 +66,11 @@ if not os.path.isdir(log_dir): lbrynet_log = os.path.join(log_dir, LOG_FILE_NAME) log = logging.getLogger(__name__) + +# TODO: configuring a logger on module import drastically reduces the +# amount of control the caller of this code has over logging +# +# Better would be to configure all logging at runtime. handler = logging.handlers.RotatingFileHandler(lbrynet_log, maxBytes=2097152, backupCount=5) log.addHandler(handler) log.setLevel(logging.INFO) @@ -466,7 +471,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): def _announce(): self.announced_startup = True self.startup_status = STARTUP_STAGES[5] - log.info("[" + str(datetime.now()) + "] Started lbrynet-daemon") + log.info("Started lbrynet-daemon") if len(self.startup_scripts): log.info("Scheduling scripts") reactor.callLater(3, self._run_scripts) @@ -488,7 +493,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): d.addCallback(lambda _: _announce()) return d - log.info("[" + str(datetime.now()) + "] Starting lbrynet-daemon") + log.info("Starting lbrynet-daemon") self.internet_connection_checker.start(3600) self.version_checker.start(3600 * 12) @@ -553,14 +558,14 @@ class LBRYDaemon(jsonrpc.JSONRPC): s = socket.create_connection((host, 80), 2) self.connected_to_internet = True except: - log.info("[" + str(datetime.now()) + "] Internet connection not working") + log.info("Internet connection not working") self.connected_to_internet = False def _check_lbrynet_connection(self): def _log_success(): - log.info("[" + str(datetime.now()) + "] lbrynet connectivity test passed") + log.info("lbrynet connectivity test passed") def _log_failure(): - log.info("[" + str(datetime.now()) + "] lbrynet connectivity test failed") + log.info("lbrynet connectivity test failed") wonderfullife_sh = "6f3af0fa3924be98a54766aa2715d22c6c1509c3f7fa32566df4899a41f3530a9f97b2ecb817fa1dcbf1b30553aefaa7" d = download_sd_blob(self.session, wonderfullife_sh, self.session.base_payment_rate_manager) @@ -578,7 +583,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): self.git_lbryum_version = version return defer.succeed(None) except: - log.info("[" + str(datetime.now()) + "] Failed to get lbryum version from git") + log.info("Failed to get lbryum version from git") self.git_lbryum_version = None return defer.fail(None) @@ -593,7 +598,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): self.git_lbrynet_version = vr return defer.succeed(None) except: - log.info("[" + str(datetime.now()) + "] Failed to get lbrynet version from git") + log.info("Failed to get lbrynet version from git") self.git_lbrynet_version = None return defer.fail(None) @@ -1091,15 +1096,15 @@ class LBRYDaemon(jsonrpc.JSONRPC): return d d.addCallback(lambda _: finish_deletion(lbry_file)) - d.addCallback(lambda _: log.info("[" + str(datetime.now()) + "] Delete lbry file")) + d.addCallback(lambda _: log.info("Delete lbry file")) return d def _get_est_cost(self, name): def _check_est(d, name): if isinstance(d.result, float): - log.info("[" + str(datetime.now()) + "] Cost est for lbry://" + name + ": " + str(d.result) + "LBC") + log.info("Cost est for lbry://" + name + ": " + str(d.result) + "LBC") else: - log.info("[" + str(datetime.now()) + "] Timeout estimating cost for lbry://" + name + ", using key fee") + log.info("Timeout estimating cost for lbry://" + name + ", using key fee") d.cancel() return defer.succeed(None) @@ -1294,7 +1299,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): Returns: true if daemon completed startup, otherwise false """ - log.info("[" + str(datetime.now()) + "] is_running: " + str(self.announced_startup)) + log.info("is_running: " + str(self.announced_startup)) if self.announced_startup: return self._render_response(True, OK_CODE) @@ -1332,7 +1337,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): else: r['message'] = "Catching up with the blockchain" r['progress'] = 0 - log.info("[" + str(datetime.now()) + "] daemon status: " + str(r)) + log.info("daemon status: " + str(r)) return self._render_response(r, OK_CODE) def jsonrpc_is_first_run(self): @@ -1345,7 +1350,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): True if first run, otherwise False """ - log.info("[" + str(datetime.now()) + "] Check if is first run") + log.info("Check if is first run") try: d = self.session.wallet.is_first_run() except: @@ -1365,7 +1370,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): Startup message, such as first run notification """ - log.info("[" + str(datetime.now()) + "] Get startup notice") + log.info("Get startup notice") if self.first_run and not self.session.wallet.wallet_balance: return self._render_response(self.startup_message, OK_CODE) @@ -1405,7 +1410,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): 'lbryum_update_available': lbryum_version < self.git_lbryum_version } - log.info("[" + str(datetime.now()) + "] Get version info: " + json.dumps(msg)) + log.info("Get version info: " + json.dumps(msg)) return self._render_response(msg, OK_CODE) def jsonrpc_get_settings(self): @@ -1433,7 +1438,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): 'start_lbrycrdd': bool, """ - log.info("[" + str(datetime.now()) + "] Get daemon settings") + log.info("Get daemon settings") return self._render_response(self.session_settings, OK_CODE) def jsonrpc_set_settings(self, p): @@ -1454,7 +1459,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): """ def _log_settings_change(): - log.info("[" + str(datetime.now()) + "] Set daemon settings to " + json.dumps(self.session_settings)) + log.info("Set daemon settings to " + json.dumps(self.session_settings)) d = self._update_settings(p) d.addErrback(lambda err: log.info(err.getTraceback())) @@ -1497,7 +1502,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): balance, float """ - log.info("[" + str(datetime.now()) + "] Get balance") + log.info("Get balance") return self._render_response(float(self.session.wallet.wallet_balance), OK_CODE) def jsonrpc_stop(self): @@ -1727,7 +1732,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): return defer.DeferredList(ds) def _disp(results): - log.info('[' + str(datetime.now()) + '] Found ' + str(len(results)) + ' search results') + log.info('Found ' + str(len(results)) + ' search results') consolidated_results = [] for r in results: t = {} @@ -1741,7 +1746,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): return consolidated_results - log.info('[' + str(datetime.now()) + '] Search nametrie: ' + search) + log.info('Search nametrie: ' + search) d = self.session.wallet.get_nametrie() d.addCallback(lambda trie: [claim for claim in trie if claim['name'].startswith(search) and 'txid' in claim]) @@ -1829,7 +1834,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): return server.failure def _disp(x): - log.info("[" + str(datetime.now()) + "] Abandoned name claim tx " + str(x)) + log.info("Abandoned name claim tx " + str(x)) return self._render_response(x, OK_CODE) d = defer.Deferred() @@ -1940,7 +1945,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): """ def _disp(address): - log.info("[" + str(datetime.now()) + "] Got new wallet address: " + address) + log.info("Got new wallet address: " + address) return defer.succeed(address) d = self.session.wallet.get_new_address() @@ -2132,7 +2137,7 @@ class LBRYDaemon(jsonrpc.JSONRPC): exclude_previous = True if 'message' in p.keys(): - log.info("[" + str(datetime.now()) + "] Upload log message: " + str(p['message'])) + log.info("Upload log message: " + str(p['message'])) if 'force' in p.keys(): force = p['force'] @@ -2287,7 +2292,7 @@ class _DownloadNameHelper(object): def _disp_file(self, f): file_path = os.path.join(self.download_directory, f.file_name) - log.info("[%s] Already downloaded: %s --> %s", datetime.now(), f.sd_hash, file_path) + log.info("Already downloaded: %s --> %s", f.sd_hash, file_path) return f def _remove_from_wait(self, r): diff --git a/lbrynet/lbrynet_daemon/LBRYDaemonControl.py b/lbrynet/lbrynet_daemon/LBRYDaemonControl.py index 309570873..cdde77c6b 100644 --- a/lbrynet/lbrynet_daemon/LBRYDaemonControl.py +++ b/lbrynet/lbrynet_daemon/LBRYDaemonControl.py @@ -25,8 +25,13 @@ if not os.path.isdir(log_dir): os.mkdir(log_dir) lbrynet_log = os.path.join(log_dir, LOG_FILE_NAME) + +DEFAULT_FORMAT = "%(asctime)s %(levelname)-8s %(name)s:%(lineno)d: %(message)s" +DEFAULT_FORMATTER = logging.Formatter(DEFAULT_FORMAT) + log = logging.getLogger(__name__) handler = logging.handlers.RotatingFileHandler(lbrynet_log, maxBytes=2097152, backupCount=5) +handler.setFormatter(DEFAULT_FORMATTER) log.addHandler(handler) log.setLevel(logging.INFO) @@ -57,6 +62,13 @@ def stop(): d.callback(None) +def configureConsoleLogger(): + handler = logging.StreamHandler(sys.stdout) + handler.setFormatter(DEFAULT_FORMATTER) + logging.getLogger().addHandler(handler) + logging.getLogger().setLevel(level=logging.INFO) + + def start(): parser = argparse.ArgumentParser(description="Launch lbrynet-daemon") parser.add_argument("--wallet", @@ -75,7 +87,7 @@ def start(): args = parser.parse_args() if args.logtoconsole: - logging.basicConfig(level=logging.INFO) + configureConsoleLogger() args = parser.parse_args() @@ -121,4 +133,4 @@ def start(): return if __name__ == "__main__": - start() \ No newline at end of file + start() diff --git a/lbrynet/lbrynet_daemon/LBRYDaemonServer.py b/lbrynet/lbrynet_daemon/LBRYDaemonServer.py index 74906da0b..507eb025d 100644 --- a/lbrynet/lbrynet_daemon/LBRYDaemonServer.py +++ b/lbrynet/lbrynet_daemon/LBRYDaemonServer.py @@ -79,7 +79,7 @@ class LBRYFileStreamer(object): def pauseProducing(self): self._paused = True - log.info("[" + str(datetime.now()) + "] Pausing producer") + log.info("Pausing producer") return defer.succeed(None) def resumeProducing(self): @@ -104,7 +104,7 @@ class LBRYFileStreamer(object): self._request.write(data) self._cursor += 1 - log.info("[" + str(datetime.now()) + "] Wrote range %s-%s/%s, length: %s, readable: %s, depth: %s" % + log.info("Wrote range %s-%s/%s, length: %s, readable: %s, depth: %s" % (start_cur, self._cursor, self._file_size, self._cursor - start_cur, readable_bytes, self._depth)) self._sent_bytes = True @@ -117,12 +117,12 @@ class LBRYFileStreamer(object): self._deferred.addCallback(lambda _: threads.deferToThread(reactor.callLater, self._delay, _check_for_new_data)) return defer.succeed(None) - log.info("[" + str(datetime.now()) + "] Resuming producer") + log.info("Resuming producer") self._paused = False self._deferred.addCallback(lambda _: _check_for_new_data()) def stopProducing(self): - log.info("[" + str(datetime.now()) + "] Stopping producer") + log.info("Stopping producer") self._stopped = True # self._fileObject.close() self._deferred.addErrback(lambda err: err.trap(defer.CancelledError)) @@ -147,7 +147,7 @@ class HostedLBRYFile(resource.Resource): # # range_header = request.getAllHeaders()['range'].replace('bytes=', '').split('-') # start, stop = int(range_header[0]), range_header[1] - # log.info("[" + str(datetime.now()) + "] GET range %s-%s" % (start, stop)) + # log.info("GET range %s-%s" % (start, stop)) # path = os.path.join(self._api.download_directory, stream.file_name) # # d = stream.get_total_bytes() diff --git a/lbrynet/lbrynet_daemon/LBRYDownloader.py b/lbrynet/lbrynet_daemon/LBRYDownloader.py index c72444c70..9187cc56d 100644 --- a/lbrynet/lbrynet_daemon/LBRYDownloader.py +++ b/lbrynet/lbrynet_daemon/LBRYDownloader.py @@ -147,6 +147,6 @@ class GetStream(object): d = _pay_key_fee() self.downloader = downloader self.download_path = os.path.join(downloader.download_directory, downloader.file_name) - d.addCallback(lambda _: log.info("[%s] Downloading %s --> %s" % (datetime.now(), self.stream_hash, self.downloader.file_name))) + d.addCallback(lambda _: log.info("Downloading %s --> %s", self.stream_hash, self.downloader.file_name)) d.addCallback(lambda _: self.downloader.start()) diff --git a/lbrynet/lbrynet_daemon/LBRYPublisher.py b/lbrynet/lbrynet_daemon/LBRYPublisher.py index c0658bfec..bd5c50e4b 100644 --- a/lbrynet/lbrynet_daemon/LBRYPublisher.py +++ b/lbrynet/lbrynet_daemon/LBRYPublisher.py @@ -48,9 +48,7 @@ class Publisher(object): def start(self, name, file_path, bid, metadata, fee=None, sources={}): def _show_result(): - - message = "[%s] Published %s --> lbry://%s txid: %s" % (datetime.now(), self.file_name, self.publish_name, self.txid) - log.info(message) + log.info("Published %s --> lbry://%s txid: %s", self.file_name, self.publish_name, self.txid) return defer.succeed(self.txid) self.publish_name = name