Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix subprocess logging during database creation #726

Open
wants to merge 1 commit into
base: main
Choose a base branch
from

Conversation

dylanmcreynolds
Copy link
Contributor

fixes #721

@dylanmcreynolds dylanmcreynolds requested review from danielballan and padraic-shafer and removed request for padraic-shafer April 23, 2024 16:49
Copy link
Contributor

@padraic-shafer padraic-shafer left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Minor typos. Otherwise looks reasonable.

Comment on lines 552 to 553
# and fails if an error logg happens. This could catch anything that is
# and error during the app build.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@danielballan
Copy link
Member

danielballan commented Apr 24, 2024

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
Copy link
Contributor Author

dylanmcreynolds commented Apr 24, 2024

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

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
Copy link
Member

danielballan commented Apr 24, 2024

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

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

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
Copy link
Contributor Author

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
Copy link
Member

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Refine logging of database creation
3 participants