Fix subprocess logging during database creation

[dylanmcreynolds]

fixes #721

[danielballan]

On main:

$ tiled serve catalog --init /tmp/test1.db
This catalog will be served as read-only. To make it writable, specify a writable directory with --write.
ERROR:root:Subprocess stderr: Database sqlite+aiosqlite:////tmp/test1.db is new. Creating tables.
Database initialized.


    Navigate a web browser or connect a Tiled client to:

    http://127.0.0.1:8000?api_key=ba083174e30b9ba3bd31e60c97b449b7ec897488cafaf5e908c0882da954cc97


INFO:     Started server process [106980]
INFO:     Waiting for application startup.
Tiled version 0.1.0a117.dev57+g0cd0407b
INFO:tiled.server.app:Tiled version 0.1.0a117.dev57+g0cd0407b
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)

On this PR branch:

$ tiled serve catalog --init /tmp/test2.db
This catalog will be served as read-only. To make it writable, specify a writable directory with --write.

    Navigate a web browser or connect a Tiled client to:

    http://127.0.0.1:8000?api_key=bc38486a80a3da8b8e1c1ce6f6143711e3721dacef159a0de7bb74789ff1be35


INFO:     Started server process [107337]
INFO:     Waiting for application startup.
Tiled version 0.1.0a117.dev57+g0cd0407b
INFO:tiled.server.app:Tiled version 0.1.0a117.dev57+g0cd0407b
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)

The INFO logging from this logger passes unhandled. Were you hoping to see logging output via this entrypoint @dylanmcreynolds?

[dylanmcreynolds]

The INFO logging from this logger passes unhandled. Were you hoping to see logging output via this entrypoint @dylanmcreynolds?

@danielballan, thanks for the catch. Looked into this more, if in the from_uri function where I'm trying to log this subprocess, this code retgurs logging.NOTSET:

 print(f"log_level:  {logging.getLevelName(logger.level)}")

Looking at the code tiled.commandline._serve.py has code to set log level (if verbose, which appears to be true): https://github.com/bluesky/tiled/blob/0cd0407be2c0e68c89a1d03e686e619aa8ddd80e/tiled/commandline/_serve.py#L176

I confirmed that I see my message through that path:

tiled serve directory /tmp
Creating catalog database at /tmp/tmp4p0xmdrd/catalog.db

    Navigate a web browser or connect a Tiled client to:

    http://127.0.0.1:8000?api_key=...

There is no such code in serve_catalog, log levels aren't set, and so calls to logger.log() are ignored.

Should this PR also fix this?

[danielballan]

Python's default behavior is to display WARNING level and above (ERROR, CRITICAL) but not INFO or DEBUG. If we want messages from a certain logger at INFO level to appear, we'll need to register a logging handler somewhere.

This message

Creating catalog database at /tmp/tmp4p0xmdrd/catalog.db

comes from

https://github.com/bluesky/tiled/blob/0cd0407be2c0e68c89a1d03e686e619aa8ddd80e/tiled/commandline/_serve.py#L111-L114

I don't think your log message appears under any conditions, in this branch, so I guess we should address that in this PR.

We'll need something in the spirit of

https://github.com/bluesky/tiled/blob/0cd0407be2c0e68c89a1d03e686e619aa8ddd80e/tiled/commandline/_serve.py#L176-L178

Maybe:

from tiled.catalog.adapter import logger as catalog_logger

catalog_logger.addHandler(StreamHandler()) 
catalog_logger.setLevel("INFO") 

[dylanmcreynolds]

from tiled.catalog.adapter import logger as catalog_logger

catalog_logger.addHandler(StreamHandler()) 
catalog_logger.setLevel("INFO") 

Woudl you want to also add the verbosity parameter that serve_directory has? Or add something a little more featured where we can pass in the text representation of logging level?

[danielballan]

I have an open mind. One pattern we've used in caproto is to count the number of v's, so -v is INFO and -vv is DEBUG and -vvvvvvv is also DEBUG.