logging cleanup

This commit is contained in:
ed 2021-03-06 17:38:56 +01:00
parent 6ecd745323
commit 57d994422d
12 changed files with 80 additions and 66 deletions

View file

@ -6,7 +6,7 @@ import re
import threading import threading
from .__init__ import PY2, WINDOWS from .__init__ import PY2, WINDOWS
from .util import undot, Pebkac, fsdec, fsenc, statdir from .util import undot, Pebkac, fsdec, fsenc, statdir, uprint
class VFS(object): class VFS(object):
@ -106,7 +106,7 @@ class VFS(object):
"""return user-readable [fsdir,real,virt] items at vpath""" """return user-readable [fsdir,real,virt] items at vpath"""
virt_vis = {} # nodes readable by user virt_vis = {} # nodes readable by user
abspath = self.canonical(rem) abspath = self.canonical(rem)
real = list(statdir(print, scandir, lstat, abspath)) real = list(statdir(uprint, scandir, lstat, abspath))
real.sort() real.sort()
if not rem: if not rem:
for name, vn2 in sorted(self.nodes.items()): for name, vn2 in sorted(self.nodes.items()):
@ -147,8 +147,8 @@ class AuthSrv(object):
self.mutex = threading.Lock() self.mutex = threading.Lock()
self.reload() self.reload()
def log(self, msg): def log(self, msg, c=0):
self.log_func("auth", msg) self.log_func("auth", msg, c)
def invert(self, orig): def invert(self, orig):
if PY2: if PY2:
@ -304,9 +304,9 @@ class AuthSrv(object):
if missing_users: if missing_users:
self.log( self.log(
"\033[31myou must -a the following users: " "you must -a the following users: "
+ ", ".join(k for k in sorted(missing_users)) + ", ".join(k for k in sorted(missing_users)),
+ "\033[0m" c=1,
) )
raise Exception("invalid config") raise Exception("invalid config")
@ -329,8 +329,8 @@ class AuthSrv(object):
v, _ = vfs.get("/", "*", False, True) v, _ = vfs.get("/", "*", False, True)
if self.warn_anonwrite and os.getcwd() == v.realpath: if self.warn_anonwrite and os.getcwd() == v.realpath:
self.warn_anonwrite = False self.warn_anonwrite = False
msg = "\033[31manyone can read/write the current directory: {}\033[0m" msg = "anyone can read/write the current directory: {}"
self.log(msg.format(v.realpath)) self.log(msg.format(v.realpath), c=1)
except Pebkac: except Pebkac:
self.warn_anonwrite = True self.warn_anonwrite = True

View file

@ -49,11 +49,11 @@ class MpWorker(object):
# print('k') # print('k')
pass pass
def log(self, src, msg): def log(self, src, msg, c=0):
self.q_yield.put([0, "log", [src, msg]]) self.q_yield.put([0, "log", [src, msg, c]])
def logw(self, msg): def logw(self, msg, c=0):
self.log("mp{}".format(self.n), msg) self.log("mp{}".format(self.n), msg, c)
def httpdrop(self, addr): def httpdrop(self, addr):
self.q_yield.put([0, "httpdrop", [addr]]) self.q_yield.put([0, "httpdrop", [addr]])
@ -73,7 +73,7 @@ class MpWorker(object):
if PY2: if PY2:
sck = pickle.loads(sck) # nosec sck = pickle.loads(sck) # nosec
self.log("%s %s" % addr, "\033[1;30m|%sC-qpop\033[0m" % ("-" * 4,)) self.log("%s %s" % addr, "|%sC-qpop" % ("-" * 4,), c="1;30")
self.httpsrv.accept(sck, addr) self.httpsrv.accept(sck, addr)
with self.mutex: with self.mutex:

View file

@ -28,7 +28,7 @@ class BrokerThr(object):
def put(self, want_retval, dest, *args): def put(self, want_retval, dest, *args):
if dest == "httpconn": if dest == "httpconn":
sck, addr = args sck, addr = args
self.log("%s %s" % addr, "\033[1;30m|%sC-qpop\033[0m" % ("-" * 4,)) self.log("%s %s" % addr, "|%sC-qpop" % ("-" * 4,), c="1;30")
self.httpsrv.accept(sck, addr) self.httpsrv.accept(sck, addr)
else: else:

View file

@ -41,8 +41,8 @@ class HttpCli(object):
self.absolute_urls = False self.absolute_urls = False
self.out_headers = {"Access-Control-Allow-Origin": "*"} self.out_headers = {"Access-Control-Allow-Origin": "*"}
def log(self, msg): def log(self, msg, c=0):
self.log_func(self.log_src, msg) self.log_func(self.log_src, msg, c)
def _check_nonfatal(self, ex): def _check_nonfatal(self, ex):
return ex.code < 400 or ex.code == 404 return ex.code < 400 or ex.code == 404
@ -63,7 +63,7 @@ class HttpCli(object):
if not headerlines[0]: if not headerlines[0]:
# seen after login with IE6.0.2900.5512.xpsp.080413-2111 (xp-sp3) # seen after login with IE6.0.2900.5512.xpsp.080413-2111 (xp-sp3)
self.log("\033[1;31mBUG: trailing newline from previous request\033[0m") self.log("BUG: trailing newline from previous request", c="1;31")
headerlines.pop(0) headerlines.pop(0)
try: try:

View file

@ -81,8 +81,8 @@ class HttpConn(object):
def respath(self, res_name): def respath(self, res_name):
return os.path.join(E.mod, "web", res_name) return os.path.join(E.mod, "web", res_name)
def log(self, msg): def log(self, msg, c=0):
self.log_func(self.log_src, msg) self.log_func(self.log_src, msg, c)
def get_u2idx(self): def get_u2idx(self):
if not self.u2idx: if not self.u2idx:
@ -129,7 +129,7 @@ class HttpConn(object):
if is_https: if is_https:
if self.sr: if self.sr:
self.log("\033[1;31mTODO: cannot do https in jython\033[0m") self.log("TODO: cannot do https in jython", c="1;31")
return return
self.log_src = self.log_src.replace("[36m", "[35m") self.log_src = self.log_src.replace("[36m", "[35m")
@ -180,7 +180,7 @@ class HttpConn(object):
pass pass
else: else:
self.log("\033[35mhandshake\033[0m " + em) self.log("handshake\033[0m " + em, c=5)
return return

View file

@ -38,7 +38,7 @@ class HttpSrv(object):
def accept(self, sck, addr): def accept(self, sck, addr):
"""takes an incoming tcp connection and creates a thread to handle it""" """takes an incoming tcp connection and creates a thread to handle it"""
self.log("%s %s" % addr, "\033[1;30m|%sC-cthr\033[0m" % ("-" * 5,)) self.log("%s %s" % addr, "|%sC-cthr" % ("-" * 5,), c="1;30")
thr = threading.Thread(target=self.thr_client, args=(sck, addr)) thr = threading.Thread(target=self.thr_client, args=(sck, addr))
thr.daemon = True thr.daemon = True
thr.start() thr.start()
@ -66,11 +66,11 @@ class HttpSrv(object):
thr.start() thr.start()
try: try:
self.log("%s %s" % addr, "\033[1;30m|%sC-crun\033[0m" % ("-" * 6,)) self.log("%s %s" % addr, "|%sC-crun" % ("-" * 6,), c="1;30")
cli.run() cli.run()
finally: finally:
self.log("%s %s" % addr, "\033[1;30m|%sC-cdone\033[0m" % ("-" * 7,)) self.log("%s %s" % addr, "|%sC-cdone" % ("-" * 7,), c="1;30")
try: try:
sck.shutdown(socket.SHUT_RDWR) sck.shutdown(socket.SHUT_RDWR)
sck.close() sck.close()
@ -78,7 +78,8 @@ class HttpSrv(object):
if not MACOS: if not MACOS:
self.log( self.log(
"%s %s" % addr, "%s %s" % addr,
"\033[1;30mshut({}): {}\033[0m".format(sck.fileno(), ex), "shut({}): {}".format(sck.fileno(), ex),
c="1;30",
) )
if ex.errno not in [10038, 10054, 107, 57, 9]: if ex.errno not in [10038, 10054, 107, 57, 9]:
# 10038 No longer considered a socket # 10038 No longer considered a socket

View file

@ -28,7 +28,7 @@ class MTag(object):
try: try:
import mutagen import mutagen
except: except:
self.log("\033[33mcould not load mutagen, trying ffprobe instead") self.log("could not load mutagen, trying ffprobe instead", c=3)
self.backend = "ffprobe" self.backend = "ffprobe"
if self.backend == "ffprobe": if self.backend == "ffprobe":
@ -48,12 +48,12 @@ class MTag(object):
if self.usable and WINDOWS and sys.version_info < (3, 8): if self.usable and WINDOWS and sys.version_info < (3, 8):
self.usable = False self.usable = False
or_ffprobe = " or python >= 3.8" or_ffprobe = " or python >= 3.8"
msg = "\033[31mfound ffprobe but your python is too old; need 3.8 or newer" msg = "found ffprobe but your python is too old; need 3.8 or newer"
self.log(msg) self.log(msg, c=1)
if not self.usable: if not self.usable:
msg = "\033[31mneed mutagen{} to read media tags so please run this:\n {} -m pip install --user mutagen \033[0m" msg = "need mutagen{} to read media tags so please run this:\n {} -m pip install --user mutagen"
self.log(msg.format(or_ffprobe, os.path.basename(sys.executable))) self.log(msg.format(or_ffprobe, os.path.basename(sys.executable)), c=1)
return return
# https://picard-docs.musicbrainz.org/downloads/MusicBrainz_Picard_Tag_Map.html # https://picard-docs.musicbrainz.org/downloads/MusicBrainz_Picard_Tag_Map.html
@ -125,8 +125,8 @@ class MTag(object):
} }
# self.get = self.compare # self.get = self.compare
def log(self, msg): def log(self, msg, c=0):
self.log_func("mtag", msg) self.log_func("mtag", msg, c)
def normalize_tags(self, ret, md): def normalize_tags(self, ret, md):
for k, v in dict(md).items(): for k, v in dict(md).items():
@ -295,9 +295,7 @@ class MTag(object):
sec *= 60 sec *= 60
sec += int(f) sec += int(f)
except: except:
self.log( self.log("invalid timestr from ffmpeg: [{}]".format(tstr), c=3)
"\033[33minvalid timestr from ffmpeg: [{}]".format(tstr)
)
ret[".dur"] = sec ret[".dur"] = sec
m = ptn_br1.search(ln) m = ptn_br1.search(ln)

View file

@ -65,10 +65,10 @@ class SvcHub(object):
self.broker.shutdown() self.broker.shutdown()
print("nailed it") print("nailed it")
def _log_disabled(self, src, msg): def _log_disabled(self, src, msg, c=0):
pass pass
def _log_enabled(self, src, msg): def _log_enabled(self, src, msg, c=0):
"""handles logging from all components""" """handles logging from all components"""
with self.log_mutex: with self.log_mutex:
now = time.time() now = time.time()
@ -91,6 +91,13 @@ class SvcHub(object):
msg = self.ansi_re.sub("", msg) msg = self.ansi_re.sub("", msg)
if "\033" in src: if "\033" in src:
src = self.ansi_re.sub("", src) src = self.ansi_re.sub("", src)
elif c:
if isinstance(c, int):
msg = "\033[3{}m{}".format(c, msg)
elif "\033" not in c:
msg = "\033[{}m{}\033[0m".format(c, msg)
else:
msg = "{}{}\033[0m".format(c, msg)
ts = datetime.utcfromtimestamp(now).strftime("%H:%M:%S.%f")[:-3] ts = datetime.utcfromtimestamp(now).strftime("%H:%M:%S.%f")[:-3]
msg = fmt.format(ts, src, msg) msg = fmt.format(ts, src, msg)

View file

@ -68,21 +68,22 @@ class TcpSrv(object):
self.log("tcpsrv", "listening @ {0}:{1}".format(ip, port)) self.log("tcpsrv", "listening @ {0}:{1}".format(ip, port))
while True: while True:
self.log("tcpsrv", "\033[1;30m|%sC-ncli\033[0m" % ("-" * 1,)) self.log("tcpsrv", "|%sC-ncli" % ("-" * 1,), c="1;30")
if self.num_clients.v >= self.args.nc: if self.num_clients.v >= self.args.nc:
time.sleep(0.1) time.sleep(0.1)
continue continue
self.log("tcpsrv", "\033[1;30m|%sC-acc1\033[0m" % ("-" * 2,)) self.log("tcpsrv", "|%sC-acc1" % ("-" * 2,), c="1;30")
ready, _, _ = select.select(self.srv, [], []) ready, _, _ = select.select(self.srv, [], [])
for srv in ready: for srv in ready:
sck, addr = srv.accept() sck, addr = srv.accept()
sip, sport = srv.getsockname() sip, sport = srv.getsockname()
self.log( self.log(
"%s %s" % addr, "%s %s" % addr,
"\033[1;30m|{}C-acc2 \033[0;36m{} \033[3{}m{}".format( "|{}C-acc2 \033[0;36m{} \033[3{}m{}".format(
"-" * 3, sip, sport % 8, sport "-" * 3, sip, sport % 8, sport
), ),
c="1;30",
) )
self.num_clients.add() self.num_clients.add()
self.hub.broker.put(False, "httpconn", sck, addr) self.hub.broker.put(False, "httpconn", sck, addr)

View file

@ -26,8 +26,8 @@ class U2idx(object):
self.cur = {} self.cur = {}
def log(self, msg): def log(self, msg, c=0):
self.log_func("u2idx", msg) self.log_func("u2idx", msg, c)
def fsearch(self, vols, body): def fsearch(self, vols, body):
"""search by up2k hashlist""" """search by up2k hashlist"""

View file

@ -91,7 +91,7 @@ class Up2k(object):
self.log("could not initialize sqlite3, will use in-memory registry only") self.log("could not initialize sqlite3, will use in-memory registry only")
# this is kinda jank # this is kinda jank
auth = AuthSrv(self.args, self.log, False) auth = AuthSrv(self.args, self.log_func, False)
have_e2d = self.init_indexes(auth) have_e2d = self.init_indexes(auth)
if have_e2d: if have_e2d:
@ -107,8 +107,8 @@ class Up2k(object):
thr.daemon = True thr.daemon = True
thr.start() thr.start()
def log(self, msg): def log(self, msg, c=0):
self.log_func("up2k", msg + "\033[K") self.log_func("up2k", msg + "\033[K", c)
def w8enc(self, rd, fn): def w8enc(self, rd, fn):
ret = [] ret = []
@ -170,8 +170,8 @@ class Up2k(object):
modified = True modified = True
if modified: if modified:
msg = "\033[33mdisabling -e2t because your sqlite belongs in a museum" msg = "disabling -e2t because your sqlite belongs in a museum"
self.log(msg) self.log(msg, c=3)
live_vols = [] live_vols = []
for vol in vols: for vol in vols:
@ -179,7 +179,7 @@ class Up2k(object):
os.listdir(vol.realpath) os.listdir(vol.realpath)
live_vols.append(vol) live_vols.append(vol)
except: except:
self.log("\033[31mcannot access " + vol.realpath) self.log("cannot access " + vol.realpath, c=1)
vols = live_vols vols = live_vols
@ -230,8 +230,8 @@ class Up2k(object):
self.log(msg.format(len(vols), time.time() - t0)) self.log(msg.format(len(vols), time.time() - t0))
if needed_mutagen: if needed_mutagen:
msg = "\033[31mcould not read tags because no backends are available (mutagen or ffprobe)\033[0m" msg = "could not read tags because no backends are available (mutagen or ffprobe)"
self.log(msg) self.log(msg, c=1)
return have_e2d return have_e2d
@ -526,8 +526,9 @@ class Up2k(object):
n = self._tag_file(write_cur, entags, wark, abspath, tags) n = self._tag_file(write_cur, entags, wark, abspath, tags)
self.n_mtag_tags_added += n self.n_mtag_tags_added += n
except: except:
msg = "\033[33m{} failed to read tags from {}:\n{}" ex = traceback.format_exc()
self.log(msg.format(self.mtag.backend, abspath, traceback.format_exc())) msg = "{} failed to read tags from {}:\n{}"
self.log(msg.format(self.mtag.backend, abspath, ex), c=3)
q.task_done() q.task_done()
@ -1071,12 +1072,12 @@ class Up2k(object):
with self.mutex: with self.mutex:
cur = self.cur[ptop] cur = self.cur[ptop]
if not cur: if not cur:
self.log("\033[31mno cursor to write tags with??") self.log("no cursor to write tags with??", c=1)
continue continue
entags = self.entags[ptop] entags = self.entags[ptop]
if not entags: if not entags:
self.log("\033[33mno entags okay.jpg") self.log("no entags okay.jpg", c=3)
continue continue
if "e2t" in self.flags[ptop]: if "e2t" in self.flags[ptop]:

View file

@ -119,19 +119,22 @@ class ProgressPrinter(threading.Thread):
continue continue
msg = self.msg msg = self.msg
m = " {}\033[K\r".format(msg) uprint(" {}\033[K\r".format(msg))
try:
print(m, end="")
except UnicodeEncodeError:
try:
print(m.encode("utf-8", "replace").decode(), end="")
except:
print(m.encode("ascii", "replace").decode(), end="")
print("\033[K", end="") print("\033[K", end="")
sys.stdout.flush() # necessary on win10 even w/ stderr btw sys.stdout.flush() # necessary on win10 even w/ stderr btw
def uprint(msg):
try:
print(msg, end="")
except UnicodeEncodeError:
try:
print(msg.encode("utf-8", "replace").decode(), end="")
except:
print(msg.encode("ascii", "replace").decode(), end="")
@contextlib.contextmanager @contextlib.contextmanager
def ren_open(fname, *args, **kwargs): def ren_open(fname, *args, **kwargs):
fdir = kwargs.pop("fdir", None) fdir = kwargs.pop("fdir", None)
@ -734,7 +737,8 @@ def statdir(logger, scandir, lstat, top):
try: try:
yield [fsdec(fh.name), fh.stat(follow_symlinks=not lstat)] yield [fsdec(fh.name), fh.stat(follow_symlinks=not lstat)]
except Exception as ex: except Exception as ex:
logger("scan-stat: {} @ {}".format(repr(ex), fsdec(fh.path))) msg = "scan-stat: \033[36m{} @ {}"
logger(msg.format(repr(ex), fsdec(fh.path)))
else: else:
src = "listdir" src = "listdir"
fun = os.lstat if lstat else os.stat fun = os.lstat if lstat else os.stat
@ -743,9 +747,11 @@ def statdir(logger, scandir, lstat, top):
try: try:
yield [fsdec(name), fun(abspath)] yield [fsdec(name), fun(abspath)]
except Exception as ex: except Exception as ex:
logger("list-stat: {} @ {}".format(repr(ex), fsdec(abspath))) msg = "list-stat: \033[36m{} @ {}"
logger(msg.format(repr(ex), fsdec(abspath)))
except Exception as ex: except Exception as ex:
logger("{}: {} @ {}".format(src, repr(ex), top)) logger("{}: \033[31m{} @ {}".format(src, repr(ex), top))
def unescape_cookie(orig): def unescape_cookie(orig):