Unify uvicorn and backend logging (#4034)

## What type of PR is this? (check all applicable)

- [ X] Feature

## Have you discussed this change with the InvokeAI team?
- [ X] Yes

      
## Have you updated all relevant documentation?
- [ X] Yes - this makes invokeai behave the way it is described in
LOGGING.md

## Description

Prior to this PR, the uvicorn embedded web server did all its logging
independently of the InvokeAI logging infrastructure, and none of the
command-line or `invokeai.yaml` configuration directives, such as
`log_level` had any effect on its output. This PR replaces the uvicorn
logger with InvokeAI's, simultaneously creating a more uniform output
experience, as well as a unified way to control the amount and
destination of the logs.

Here's what we used to see at startup:
```
[2023-07-27 07:29:48,027]::[InvokeAI]::INFO --> InvokeAI version 3.0.1rc2                                                                                                                               
[2023-07-27 07:29:48,027]::[InvokeAI]::INFO --> Root directory = /home/lstein/invokeai-main                                                                                                             
[2023-07-27 07:29:48,028]::[InvokeAI]::INFO --> GPU device = cuda NVIDIA GeForce RTX 4070                                                                                                               
[2023-07-27 07:29:48,040]::[InvokeAI]::INFO --> Scanning /home/lstein/invokeai-main/models for new models                                                                                               
[2023-07-27 07:29:49,263]::[InvokeAI]::INFO --> Scanned 22 files and directories, imported 10 models                                                                                                    
[2023-07-27 07:29:49,271]::[InvokeAI]::INFO --> Model manager service initialized                                                                                                                       
INFO:     Application startup complete.                                                                                                                                                                 
INFO:     Uvicorn running on http://127.0.0.1:9090 (Press CTRL+C to quit)                                                                                                                               
INFO:     127.0.0.1:44404 - "GET /socket.io/?EIO=4&transport=polling&t=OcN7Pvd HTTP/1.1" 200 OK                                                                                                         
INFO:     127.0.0.1:44404 - "POST /socket.io/?EIO=4&transport=polling&t=OcN7Pw6&sid=SB-NsBKLSrW7YtM0AAAA HTTP/1.1" 200 OK                                                                               
INFO:     ('127.0.0.1', 44418) - "WebSocket /socket.io/?EIO=4&transport=websocket&sid=SB-NsBKLSrW7YtM0AAAA" [accepted]                                                                                  
INFO:     connection open                                                                                                                                                                               
INFO:     127.0.0.1:44430 - "GET /socket.io/?EIO=4&transport=polling&t=OcN7Pw9&sid=SB-NsBKLSrW7YtM0AAAA HTTP/1.1" 200 OK                                                                                
INFO:     127.0.0.1:44404 - "GET /socket.io/?EIO=4&transport=polling&t=OcN7PwU&sid=SB-NsBKLSrW7YtM0AAAA HTTP/1.1" 200 OK                                                                                
INFO:     127.0.0.1:44404 - "GET /api/v1/images/?is_intermediate=true HTTP/1.1" 200 OK                                                                                                                  
INFO:     127.0.0.1:43448 - "GET / HTTP/1.1" 200 OK                                                                                                                                                     
INFO:     connection closed                                                                                                                                                                             
INFO:     127.0.0.1:43448 - "GET /assets/index-5a784cdd.js HTTP/1.1" 200 OK                                                                                                                             
INFO:     127.0.0.1:43458 - "GET /assets/favicon-0d253ced.ico HTTP/1.1" 304 Not Modified                                                                                                                
INFO:     127.0.0.1:43448 - "GET /locales/en.json HTTP/1.1" 200 OK                                                                                                                                      
```

And here's what we see with the new implementation:
```
[2023-07-27 12:05:28,810]::[uvicorn.error]::INFO --> Started server process [875161]
[2023-07-27 12:05:28,810]::[uvicorn.error]::INFO --> Waiting for application startup.
[2023-07-27 12:05:28,810]::[InvokeAI]::INFO --> InvokeAI version 3.0.1rc2
[2023-07-27 12:05:28,810]::[InvokeAI]::INFO --> Root directory = /home/lstein/invokeai-main
[2023-07-27 12:05:28,811]::[InvokeAI]::INFO --> GPU device = cuda NVIDIA GeForce RTX 4070
[2023-07-27 12:05:28,823]::[InvokeAI]::INFO --> Scanning /home/lstein/invokeai-main/models for new models
[2023-07-27 12:05:29,970]::[InvokeAI]::INFO --> Scanned 22 files and directories, imported 10 models
[2023-07-27 12:05:29,977]::[InvokeAI]::INFO --> Model manager service initialized
[2023-07-27 12:05:29,980]::[uvicorn.error]::INFO --> Application startup complete.
[2023-07-27 12:05:29,981]::[uvicorn.error]::INFO --> Uvicorn running on http://127.0.0.1:9090 (Press CTRL+C to quit)
[2023-07-27 12:05:32,140]::[uvicorn.access]::INFO --> 127.0.0.1:45236 - "GET /socket.io/?EIO=4&transport=polling&t=OcO6ILb HTTP/1.1" 200
[2023-07-27 12:05:32,142]::[uvicorn.access]::INFO --> 127.0.0.1:45248 - "GET /socket.io/?EIO=4&transport=polling&t=OcO6ILb HTTP/1.1" 200
[2023-07-27 12:05:32,154]::[uvicorn.access]::INFO --> 127.0.0.1:45236 - "POST /socket.io/?EIO=4&transport=polling&t=OcO6ILr&sid=13O4-5uLx5eP-NuqAAAA HTTP/1.1" 200
[2023-07-27 12:05:32,168]::[uvicorn.access]::INFO --> 127.0.0.1:45252 - "POST /socket.io/?EIO=4&transport=polling&t=OcO6IM0&sid=0KRqxmh7JLc8t7wZAAAB HTTP/1.1" 200
[2023-07-27 12:05:32,171]::[uvicorn.error]::INFO --> ('127.0.0.1', 45264) - "WebSocket /socket.io/?EIO=4&transport=websocket&sid=0KRqxmh7JLc8t7wZAAAB" [accepted]
[2023-07-27 12:05:32,172]::[uvicorn.error]::INFO --> connection open
[2023-07-27 12:05:32,174]::[uvicorn.access]::INFO --> 127.0.0.1:45276 - "GET /socket.io/?EIO=4&transport=polling&t=OcO6IM3&sid=0KRqxmh7JLc8t7wZAAAB HTTP/1.1" 200

```

You can also divert everything to a file with a `invokeai.yaml` entry
like this:
```
  Logging:
    log_handlers:
    - file=/home/lstein/invokeai/logs/access_log
    log_format: plain
    log_level: info
```

This works with syslog and other log handlers as well.
This commit is contained in:
Lincoln Stein 2023-07-27 15:56:42 -04:00 committed by GitHub
commit bb9460d278
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
9 changed files with 46 additions and 26 deletions

View File

@ -3,6 +3,7 @@ import asyncio
import sys
from inspect import signature
import logging
import uvicorn
import socket
@ -210,11 +211,25 @@ def invoke_api():
port = find_port(app_config.port)
if port != app_config.port:
logger.warn(f"Port {app_config.port} in use, using port {port}")
# Start our own event loop for eventing usage
loop = asyncio.new_event_loop()
config = uvicorn.Config(app=app, host=app_config.host, port=port, loop=loop)
# Use access_log to turn off logging
config = uvicorn.Config(
app=app,
host=app_config.host,
port=port,
loop=loop,
log_level=app_config.log_level,
)
server = uvicorn.Server(config)
# replace uvicorn's loggers with InvokeAI's for consistent appearance
for logname in ["uvicorn.access", "uvicorn"]:
l = logging.getLogger(logname)
l.handlers.clear()
for ch in logger.handlers:
l.addHandler(ch)
loop.run_until_complete(server.serve())

View File

@ -1,4 +1,4 @@
import{A as g,fS as Xe,z as x,a4 as Ba,fT as Ea,af as ca,aj as c,fU as b,al as Da,fV as t,fW as Ra,fX as h,fY as ba,fZ as ja,f_ as Ha,aI as Wa,f$ as Va,ad as La,g0 as qa}from"./index-89941396.js";import{n,o as Sr,p as Oa,T as Na,q as Ga,s as Ua,t as Ya,v as Xa,w as Ka,x as Za,y as Ja,z as Qa,A as et,B as rt,D as at,E as tt,F as ot,G as nt,e as it,M as lt}from"./MantineProvider-8184f020.js";var va=String.raw,ua=va`
import{A as g,fS as Xe,z as x,a4 as Ba,fT as Ea,af as ca,aj as c,fU as b,al as Da,fV as t,fW as Ra,fX as h,fY as ba,fZ as ja,f_ as Ha,aI as Wa,f$ as Va,ad as La,g0 as qa}from"./index-5a784cdd.js";import{n,o as Sr,p as Oa,T as Na,q as Ga,s as Ua,t as Ya,v as Xa,w as Ka,x as Za,y as Ja,z as Qa,A as et,B as rt,D as at,E as tt,F as ot,G as nt,e as it,M as lt}from"./MantineProvider-ea42d3d1.js";var va=String.raw,ua=va`
:root,
:host {
--chakra-vh: 100vh;

View File

@ -12,7 +12,7 @@
margin: 0;
}
</style>
<script type="module" crossorigin src="./assets/index-89941396.js"></script>
<script type="module" crossorigin src="./assets/index-5a784cdd.js"></script>
</head>
<body dir="ltr">

View File

@ -5562,12 +5562,6 @@ export type components = {
* @enum {string}
*/
StableDiffusion2ModelFormat: "checkpoint" | "diffusers";
/**
* StableDiffusion1ModelFormat
* @description An enumeration.
* @enum {string}
*/
StableDiffusion1ModelFormat: "checkpoint" | "diffusers";
/**
* StableDiffusionXLModelFormat
* @description An enumeration.
@ -5580,6 +5574,12 @@ export type components = {
* @enum {string}
*/
ControlNetModelFormat: "checkpoint" | "diffusers";
/**
* StableDiffusion1ModelFormat
* @description An enumeration.
* @enum {string}
*/
StableDiffusion1ModelFormat: "checkpoint" | "diffusers";
};
responses: never;
parameters: never;

View File

@ -42,8 +42,13 @@ export type ControlField = components['schemas']['ControlField'];
// Model Configs
export type LoRAModelConfig = components['schemas']['LoRAModelConfig'];
export type VaeModelConfig = components['schemas']['VaeModelConfig'];
export type ControlNetModelCheckpointConfig =
components['schemas']['ControlNetModelCheckpointConfig'];
export type ControlNetModelDiffusersConfig =
components['schemas']['ControlNetModelDiffusersConfig'];
export type ControlNetModelConfig =
components['schemas']['ControlNetModelConfig'];
| ControlNetModelCheckpointConfig
| ControlNetModelDiffusersConfig;
export type TextualInversionModelConfig =
components['schemas']['TextualInversionModelConfig'];
export type DiffusersModelConfig =

View File

@ -1 +1 @@
__version__ = "3.0.1rc1"
__version__ = "3.0.1rc2"