pretty logging

This commit is contained in:
Devaev Maxim 2018-06-28 21:16:11 +03:00
parent 54430fed31
commit ed331feab1
9 changed files with 74 additions and 64 deletions

View File

@ -49,7 +49,7 @@ logging:
(): contextlog.SmartFormatter (): contextlog.SmartFormatter
style: "{" style: "{"
datefmt: "%H:%M:%S" datefmt: "%H:%M:%S"
format: "[{asctime}] {name:15.15} {levelname:>7} --- {message}" format: "[{asctime}] {name:20.20} {levelname:>7} --- {message}"
handlers: handlers:
console: console:

View File

@ -1,7 +1,7 @@
import asyncio import asyncio
import logging
from .application import init from .application import init
from .logging import get_logger
from .atx import Atx from .atx import Atx
from .streamer import Streamer from .streamer import Streamer
@ -52,4 +52,4 @@ def main() -> None:
host=config["server"]["host"], host=config["server"]["host"],
port=config["server"]["port"], port=config["server"]["port"],
) )
logging.getLogger(__name__).info("Bye-bye") get_logger().info("Bye-bye")

View File

@ -1,15 +1,13 @@
import asyncio import asyncio
import logging
from typing import Tuple from typing import Tuple
from .logging import get_logger
from . import gpio from . import gpio
# ===== # =====
_logger = logging.getLogger(__name__)
class Atx: class Atx:
def __init__( def __init__(
self, self,
@ -39,15 +37,15 @@ class Atx:
async def click_power(self) -> None: async def click_power(self) -> None:
if (await self.__click(self.__power_switch, self.__click_delay)): if (await self.__click(self.__power_switch, self.__click_delay)):
_logger.info("Clicked power") get_logger().info("Clicked power")
async def click_power_long(self) -> None: async def click_power_long(self) -> None:
if (await self.__click(self.__power_switch, self.__long_click_delay)): if (await self.__click(self.__power_switch, self.__long_click_delay)):
_logger.info("Clicked power (long press)") get_logger().info("Clicked power (long press)")
async def click_reset(self) -> None: async def click_reset(self) -> None:
if (await self.__click(self.__reset_switch, self.__click_delay)): if (await self.__click(self.__reset_switch, self.__click_delay)):
_logger.info("Clicked reset") get_logger().info("Clicked reset")
async def __click(self, pin: int, delay: float) -> bool: async def __click(self, pin: int, delay: float) -> bool:
if not self.__lock.locked(): if not self.__lock.locked():

View File

@ -1,28 +1,27 @@
import subprocess import subprocess
import logging
import time import time
from ...application import init from ...application import init
from ...logging import get_logger
from ... import gpio from ... import gpio
# ===== # =====
_logger = logging.getLogger(__name__)
def main() -> None: def main() -> None:
config = init() config = init()
_logger.info("Cleaning up ...") logger = get_logger(0)
logger.info("Cleaning up ...")
with gpio.bcm(): with gpio.bcm():
for (key, pin) in [ for (key, pin) in [
*config["atx"]["switches"]["pinout"].items(), *config["atx"]["switches"]["pinout"].items(),
*config["video"]["pinout"].items(), *config["video"]["pinout"].items(),
]: ]:
_logger.info("Writing value=0 to pin=%d (%s)", pin, key) logger.info("Writing value=0 to pin=%d (%s)", pin, key)
gpio.write(pin, False) gpio.write(pin, False)
_logger.info("Trying to find and kill mjpg_streamer ...") logger.info("Trying to find and kill mjpg_streamer ...")
try: try:
subprocess.check_output(["killall", "mjpg_streamer"], stderr=subprocess.STDOUT) subprocess.check_output(["killall", "mjpg_streamer"], stderr=subprocess.STDOUT)
time.sleep(3) time.sleep(3)
@ -30,4 +29,4 @@ def main() -> None:
except subprocess.CalledProcessError: except subprocess.CalledProcessError:
pass pass
_logger.info("Bye-bye") logger.info("Bye-bye")

View File

@ -1,24 +1,23 @@
import contextlib import contextlib
import logging
from typing import Generator from typing import Generator
from RPi import GPIO from RPi import GPIO
from .logging import get_logger
# ===== # =====
_logger = logging.getLogger(__name__)
@contextlib.contextmanager @contextlib.contextmanager
def bcm() -> Generator[None, None, None]: def bcm() -> Generator[None, None, None]:
logger = get_logger(2)
GPIO.setmode(GPIO.BCM) GPIO.setmode(GPIO.BCM)
_logger.info("Configured GPIO mode as BCM") logger.info("Configured GPIO mode as BCM")
try: try:
yield yield
finally: finally:
GPIO.cleanup() GPIO.cleanup()
_logger.info("GPIO cleaned") logger.info("GPIO cleaned")
def set_output(pin: int, initial: bool=False) -> int: def set_output(pin: int, initial: bool=False) -> int:

15
kvmd/kvmd/logging.py Normal file
View File

@ -0,0 +1,15 @@
import sys
import logging
# =====
def get_logger(depth: int=1) -> logging.Logger:
frame = sys._getframe(1) # pylint: disable=protected-access
frames = []
while frame:
frames.append(frame)
frame = frame.f_back
if len(frames) - 1 >= depth:
break
name = frames[depth].f_globals["__name__"]
return logging.getLogger(name)

View File

@ -1,16 +1,14 @@
import multiprocessing import multiprocessing
import multiprocessing.queues import multiprocessing.queues
import queue import queue
import logging
import time import time
from .logging import get_logger
from . import gpio from . import gpio
# ===== # =====
_logger = logging.getLogger(__name__)
class Ps2Keyboard(multiprocessing.Process): class Ps2Keyboard(multiprocessing.Process):
def __init__(self, clock: int, data: int, pulse: float) -> None: def __init__(self, clock: int, data: int, pulse: float) -> None:
super().__init__(daemon=True) super().__init__(daemon=True)
@ -23,11 +21,11 @@ class Ps2Keyboard(multiprocessing.Process):
self.__event = multiprocessing.Event() self.__event = multiprocessing.Event()
def start(self) -> None: def start(self) -> None:
_logger.info("Starting keyboard daemon ...") get_logger().info("Starting keyboard daemon ...")
super().start() super().start()
def stop(self) -> None: def stop(self) -> None:
_logger.info("Stopping keyboard daemon ...") get_logger().info("Stopping keyboard daemon ...")
self.__event.set() self.__event.set()
self.join() self.join()
@ -35,6 +33,7 @@ class Ps2Keyboard(multiprocessing.Process):
self.__queue.put(code) self.__queue.put(code)
def run(self) -> None: def run(self) -> None:
with gpio.bcm():
try: try:
while not self.__event.is_set(): while not self.__event.is_set():
try: try:
@ -44,7 +43,7 @@ class Ps2Keyboard(multiprocessing.Process):
else: else:
self.__send_byte(code) self.__send_byte(code)
except Exception: except Exception:
_logger.exception("Unhandled exception") get_logger().exception("Unhandled exception")
raise raise
def __send_byte(self, code: int) -> None: def __send_byte(self, code: int) -> None:

View File

@ -1,7 +1,6 @@
import os import os
import signal import signal
import asyncio import asyncio
import logging
import time import time
from typing import List from typing import List
@ -15,11 +14,10 @@ from .atx import Atx
from .streamer import Streamer from .streamer import Streamer
from .ps2 import Ps2Keyboard from .ps2 import Ps2Keyboard
from .logging import get_logger
# ===== # =====
_logger = logging.getLogger(__name__)
def _system_task(method: Callable) -> Callable: def _system_task(method: Callable) -> Callable:
async def wrap(self: "Server") -> None: async def wrap(self: "Server") -> None:
try: try:
@ -27,7 +25,7 @@ def _system_task(method: Callable) -> Callable:
except asyncio.CancelledError: except asyncio.CancelledError:
pass pass
except Exception: except Exception:
_logger.exception("Unhandled exception, killing myself ...") get_logger().exception("Unhandled exception, killing myself ...")
os.kill(os.getpid(), signal.SIGTERM) os.kill(os.getpid(), signal.SIGTERM)
return wrap return wrap
@ -77,7 +75,7 @@ class Server: # pylint: disable=too-many-instance-attributes
app=app, app=app,
host=host, host=host,
port=port, port=port,
print=(lambda text: [_logger.info(line.strip()) for line in text.strip().splitlines()]), # type: ignore print=(lambda text: [get_logger().info(line.strip()) for line in text.strip().splitlines()]), # type: ignore
) )
async def __root_handler(self, _: aiohttp.web.Request) -> aiohttp.web.Response: async def __root_handler(self, _: aiohttp.web.Request) -> aiohttp.web.Response:
@ -97,12 +95,14 @@ class Server: # pylint: disable=too-many-instance-attributes
return ws return ws
async def __on_shutdown(self, _: aiohttp.web.Application) -> None: async def __on_shutdown(self, _: aiohttp.web.Application) -> None:
_logger.info("Cancelling system tasks ...") logger = get_logger(0)
logger.info("Cancelling system tasks ...")
for task in self.__system_tasks: for task in self.__system_tasks:
task.cancel() task.cancel()
await asyncio.gather(*self.__system_tasks) await asyncio.gather(*self.__system_tasks)
_logger.info("Disconnecting clients ...") logger.info("Disconnecting clients ...")
for ws in list(self.__sockets): for ws in list(self.__sockets):
await self.__remove_socket(ws) await self.__remove_socket(ws)
@ -168,20 +168,20 @@ class Server: # pylint: disable=too-many-instance-attributes
if method: if method:
await method() await method()
return None return None
_logger.warning("Received an incorrect command: %r", command) get_logger().warning("Received an incorrect command: %r", command)
return "ERROR incorrect command" return "ERROR incorrect command"
async def __register_socket(self, ws: aiohttp.web.WebSocketResponse) -> None: async def __register_socket(self, ws: aiohttp.web.WebSocketResponse) -> None:
async with self.__sockets_lock: async with self.__sockets_lock:
self.__sockets.add(ws) self.__sockets.add(ws)
_logger.info("Registered new client socket: remote=%s; id=%d; active=%d", get_logger().info("Registered new client socket: remote=%s; id=%d; active=%d",
ws._req.remote, id(ws), len(self.__sockets)) # pylint: disable=protected-access ws._req.remote, id(ws), len(self.__sockets)) # pylint: disable=protected-access
async def __remove_socket(self, ws: aiohttp.web.WebSocketResponse) -> None: async def __remove_socket(self, ws: aiohttp.web.WebSocketResponse) -> None:
async with self.__sockets_lock: async with self.__sockets_lock:
try: try:
self.__sockets.remove(ws) self.__sockets.remove(ws)
_logger.info("Removed client socket: remote=%s; id=%d; active=%d", get_logger().info("Removed client socket: remote=%s; id=%d; active=%d",
ws._req.remote, id(ws), len(self.__sockets)) # pylint: disable=protected-access ws._req.remote, id(ws), len(self.__sockets)) # pylint: disable=protected-access
await ws.close() await ws.close()
except Exception: except Exception:

View File

@ -1,17 +1,15 @@
import asyncio import asyncio
import asyncio.subprocess import asyncio.subprocess
import logging
from typing import Dict from typing import Dict
from typing import Optional from typing import Optional
from .logging import get_logger
from . import gpio from . import gpio
# ===== # =====
_logger = logging.getLogger(__name__)
class Streamer: # pylint: disable=too-many-instance-attributes class Streamer: # pylint: disable=too-many-instance-attributes
def __init__( def __init__(
self, self,
@ -38,13 +36,13 @@ class Streamer: # pylint: disable=too-many-instance-attributes
async def start(self) -> None: async def start(self) -> None:
assert not self.__proc_task assert not self.__proc_task
_logger.info("Starting mjpg_streamer ...") get_logger().info("Starting mjpg_streamer ...")
await self.__set_hw_enabled(True) await self.__set_hw_enabled(True)
self.__proc_task = self.__loop.create_task(self.__process()) self.__proc_task = self.__loop.create_task(self.__process())
async def stop(self) -> None: async def stop(self) -> None:
assert self.__proc_task assert self.__proc_task
_logger.info("Stopping mjpg_streamer ...") get_logger().info("Stopping mjpg_streamer ...")
self.__proc_task.cancel() self.__proc_task.cancel()
await asyncio.gather(self.__proc_task, return_exceptions=True) await asyncio.gather(self.__proc_task, return_exceptions=True)
await self.__set_hw_enabled(False) await self.__set_hw_enabled(False)
@ -62,6 +60,8 @@ class Streamer: # pylint: disable=too-many-instance-attributes
await asyncio.sleep(self.__sync_delay) await asyncio.sleep(self.__sync_delay)
async def __process(self) -> None: async def __process(self) -> None:
logger = get_logger(0)
proc: Optional[asyncio.subprocess.Process] = None # pylint: disable=no-member proc: Optional[asyncio.subprocess.Process] = None # pylint: disable=no-member
while True: while True:
try: try:
@ -70,13 +70,13 @@ class Streamer: # pylint: disable=too-many-instance-attributes
stdout=asyncio.subprocess.PIPE, stdout=asyncio.subprocess.PIPE,
stderr=asyncio.subprocess.STDOUT, stderr=asyncio.subprocess.STDOUT,
) )
_logger.info("Started mjpg_streamer pid=%d: %s", proc.pid, self.__cmd) logger.info("Started mjpg_streamer pid=%d: %s", proc.pid, self.__cmd)
empty = 0 empty = 0
while proc.returncode is None: while proc.returncode is None:
line = (await proc.stdout.readline()).decode(errors="ignore").strip() line = (await proc.stdout.readline()).decode(errors="ignore").strip()
if line: if line:
_logger.info("mjpg_streamer: %s", line) logger.info("mjpg_streamer: %s", line)
empty = 0 empty = 0
else: else:
empty += 1 empty += 1
@ -90,9 +90,9 @@ class Streamer: # pylint: disable=too-many-instance-attributes
break break
except Exception as err: except Exception as err:
if proc: if proc:
_logger.error("Unexpected finished mjpg_streamer pid=%d with retcode=%d", proc.pid, proc.returncode) logger.exception("Unexpected finished mjpg_streamer pid=%d with retcode=%d", proc.pid, proc.returncode)
else: else:
_logger.error("Can't start mjpg_streamer: %s", err) logger.exception("Can't start mjpg_streamer: %s", err)
await asyncio.sleep(1) await asyncio.sleep(1)
if proc: if proc: