파이썬 - uvicorn 사용자 정의 Logger 작성
uvicorn으로,
파이썬 - FastAPI / uvicorn 호스팅 환경에서 asyncio 사용하는 방법
; https://www.sysnet.pe.kr/2/0/13087
파이썬 FastAPI 앱을 호스팅하면,
from fastapi import FastAPI
import nest_asyncio
import os
nest_asyncio.apply()
app = FastAPI()
@app.get("/")
def read_root():
return "Hello world"
보통 이런 식의 출력을 볼 수 있습니다.
$ uvicorn main:app --reload --host 0.0.0.0 --port 18003 --loop asyncio
INFO: Will watch for changes in these directories: ['/mnt/d/testprj/test_fastapi']
INFO: Uvicorn running on http://0.0.0.0:18003 (Press CTRL+C to quit)
INFO: Started reloader process [7601] using watchgod
INFO: Started server process [7603]
INFO: Waiting for application startup.
INFO: Application startup complete.
그리고 만약 루트(/) 경로를 웹 브라우저에서 방문하면 이런 식의 출력이 추가됩니다.
INFO: 127.0.0.1:45578 - "GET / HTTP/1.1" 200 OK
uvicorn의 출력 로그는 크게 2가지로 나뉘는데요, 하나는 "uvicorn.error" 범주가 있고 또 하나는 "uvicorn.access"가 있습니다. 위의 출력에서 처음 uvicorn을 호스팅할 때 출력한 "INFO"는 (이름과 어울리지 않게) "uvicorn.error"에 속하고, 이후 개별 경로를 방문할 때 발생하는 로그들이 "uvicorn.access"에 속합니다.
예제 코드를 통해 보는 것이 ^^ 더 이해가 빠르겠죠? 예를 들기 위해, 로그를 UDP로 전송하는 경우를 가정해 보겠습니다. 우선, 다음과 같이 logging.Handler를 상속받는 클래스를 하나 만들면 됩니다.
class UdpLogger(logging.Handler):
def __init__(self, udp_server, udp_port):
self.endpoint = (udp_server, udp_port)
self.sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
super().__init__()
def emit(self, record):
self.sock.sendto(record.getMessage().encode(), self.endpoint)
위에서 중요한 것은 "emit" 함수인데요, 이것은
logger.Handler에 정의된 함수로, Logger.log/debug/info/warning/error/critical의 모든 호출마다 실행되는 함수입니다.
전달된 record 인자는
LogRecord Objects 타입이어서, 그 타입이 제공하는 필드를 통해 Logger.log/debug/info/warning/error/critical에서 전달한 정보를 구할 수 있습니다. 위의 코드에서는 단순히 record.getMessage()를 UDP 서버로 전송하는 것이기 때문에 사용자가 Logger.info("test")라고 하는 경우 "test"에 해당하는 문자열이 record.getMessage()로 반환됩니다.
이후, 사용은 다음과 같이 할 수 있습니다.
handler = UdpLogger('192.168.100.50', 60900)
logger = logging.getLogger("uvicorn.error")
logger.handlers = []
logger.setLevel(logging.DEBUG)
logger.addHandler(handler)
print('logger installed')
nest_asyncio.apply()
app = FastAPI()
위의 경우 setLevel을 DEBUG로 설정했는데요, Logger가 제공하는 로깅 함수의 수준이 DEBUG/INFO/WARNING/ERROR/CRITICAL 순이기 때문에 모든 로그를 handler에 전달하겠다는 것을 의미합니다.
그래서 다시 실행해 보면,
// 실제 실행된 프로세스의 Log
$ uvicorn main:app --reload --host 0.0.0.0 --port 18003 --loop asyncio
INFO: Will watch for changes in these directories: ['/mnt/d/workshop2/python-agent/testprj/latest_fastapi']
INFO: Uvicorn running on http://0.0.0.0:18003 (Press CTRL+C to quit)
INFO: Started reloader process [7667] using watchgod
logger installed
INFO: Started server process [7669]
INFO: Waiting for application startup.
INFO: Application startup complete.
INFO: 127.0.0.1:56486 - "GET / HTTP/1.1" 200 OK
이번엔 UDP 서버에 다음과 같은 출력을 얻을 수 있습니다.
// UDP 서버에서 받은 LogRecord.getMessage()
Started server process [7683]
Waiting for application startup.
Application startup complete.
보시면 print 코드를 사용한 "logger installed" 메시지가 출력된 후 "GET ..."을 제외한 로그가 들어왔습니다. 이전에 설정했듯이 "GET ..." 로그는 "access log"에 해당하기 때문에 그것도 받고 싶다면 다음과 같이 한 번 더 handler를 추가해야 합니다.
logger2 = logging.getLogger("uvicorn.access")
logger2.handlers = []
logger2.setLevel(logging.DEBUG)
logger2.addHandler(handler)
이렇게 변경하면 이제 UDP 서버 측에서도 다음의 메시지를 받게 됩니다.
127.0.0.1:56748 - "GET / HTTP/1.1" 200
여기서 한 가지 차이점이 있는데요, "uvicorn.error" 범주로 받았던 호스팅 관련 메시지들은 Logger를 추가해도 uvicorn의 콘솔 화면에 여전히 출력되는 반면 "uvicorn.access" 로그의 경우에는 uvicorn 콘솔 화면에 출력되지 않습니다.
Logger를 설정한 경우 가장 중요한 것이 예외 로그일 것입니다. 그런데 이게 좀 애매합니다. ^^; 일부러 다음과 같이 오류가 발생하도록 만들고,
@app.get("/")
def read_root():
text = None
text.split(' ')
return "Hello world"
루트를 방문하면 uvicorn 콘솔 화면에는 이렇게 예외의 모든 정보가 나오지만,
ERROR: Exception in ASGI application
Traceback (most recent call last):
File "/home/kevin/.local/lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 372, in run_asgi
result = await app(self.scope, self.receive, self.send)
...[생략]...
File "/usr/lib/python3.8/asyncio/futures.py", line 178, in result
raise self._exception
File "/home/kevin/.local/lib/python3.8/site-packages/anyio/_backends/_asyncio.py", line 867, in run
result = context.run(func, *args)
File "/mnt/d/workshop2/python-agent/testprj/latest_fastapi/./main.py", line 48, in read_root
text.split(' ')
AttributeError: 'NoneType' object has no attribute 'split'
UDP 서버에 출력된 텍스트는, 즉 UdpLogger.emit에 의해 전달된 메시지는 단순히 다음과 같습니다.
Exception in ASGI application
중요한 Traceback 정보가 없군요. ^^; 왜냐하면, 실제로 LogRecord의 getMessage() 함수가 반환하는 값이 그것뿐이기 때문입니다. 이를 위해선 record의 다른 속성을 통해 예외 메시지를 뽑아내서 전송하는 부가 처리를 이렇게 추가해야 합니다.
def emit(self, record):
import traceback
self.sock.sendto(record.getMessage().encode(), self.endpoint)
if record.exc_info is not None:
ex = record.exc_info[1]
text = traceback.format_exception(etype=type(ex), value=ex, tb=ex.__traceback__)
text = ''.join(text)
self.sock.sendto(text.encode(), self.endpoint)
한 가지 유의해야 할 점이 있다면, logging.Handler로 전달하는 값은 오직 Logger.log/debug/info/warning/error/critical 함수에 의한 호출만을 처리할 수 있다는 점입니다. 즉, uvicorn의 콘솔 화면에 출력되는 모든 메시지가 아니라는 건데요, 일례로 print 함수를 이용한 출력은 콘솔에는 나오지만 logging.Handler로는 잡을 수 없습니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]