Fix subprocess logging during database creation

[dylanmcreynolds]

fixes #721

[padraic-shafer]

Minor typos. Otherwise looks reasonable.

[padraic-shafer]

Suggested change

	# and fails if an error logg happens. This could catch anything that is
	# and error during the app build.
	# and fails if an error log happens. This could catch anything that is
	# an error during the app build.

[dylanmcreynolds]

Thanks. I fixed comments and squashed into a single commit.

[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):

tiled/tiled/commandline/_serve.py

Line 176 in 0cd0407

if verbose:

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

tiled/tiled/commandline/_serve.py

Lines 111 to 114 in 0cd0407

	typer.echo(
	f"Creating catalog database at {temp_directory / SQLITE_CATALOG_FILENAME}",
	err=True,
	)

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

tiled/tiled/commandline/_serve.py

Lines 176 to 178 in 0cd0407

	if verbose:
	register_logger.addHandler(StreamHandler())
	register_logger.setLevel("INFO")

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.