Fix subprocess logging during database creation (#726)

* fix subprocess logging

* Fix branching

---------

Co-authored-by: Dan Allan <[email protected]>

tiled/_tests/test_catalog.py

@@ -528,3 +528,34 @@ async def test_constraints_on_parameter_and_num(a, assets):
                 )
             ],
         )
+
+
+@pytest.mark.asyncio
+async def test_init_db_logging(tmpdir, caplog):
+    config = {
+        "database": {
+            "uri": "sqlite+aiosqlite://",  # in-memory
+        },
+        "trees": [
+            {
+                "tree": "catalog",
+                "path": "/",
+                "args": {
+                    "uri": f"sqlite+aiosqlite:///{tmpdir}/catalog.db",
+                    "writable_storage": str(tmpdir / "data"),
+                    "init_if_not_exists": True,
+                },
+            },
+        ],
+    }
+    # Issue 721 notes that the logging of the subprocess that creates
+    # a database logs normal things to error. This test looks at the log
+    # and fails if an error log happens. This could catch anything that is
+    # an error during the app build.
+    import logging
+
+    with caplog.at_level(logging.INFO):
+        app = build_app_from_config(config)
+        for record in caplog.records:
+            assert record.levelname != "ERROR", f"Error found creating app {record.msg}"
+        assert app

tiled/catalog/adapter.py

@@ -1397,8 +1397,8 @@ def from_uri(
         # Capture stdout and stderr from the subprocess and write to logging
         stdout = process.stdout.decode()
         stderr = process.stderr.decode()
-        logging.info(f"Subprocess stdout: {stdout}")
-        logging.error(f"Subprocess stderr: {stderr}")
+        logger.info(f"Subprocess stdout: {stdout}")
+        logger.info(f"Subprocess stderr: {stderr}")
 
     parsed_url = make_url(uri)
     if (parsed_url.get_dialect().name == "sqlite") and (

tiled/commandline/_serve.py

@@ -178,6 +178,10 @@ def serve_directory(
         adapters_by_mimetype=adapters_by_mimetype,
     )
     if verbose:
+        from tiled.catalog.adapter import logger as catalog_logger
+
+        catalog_logger.addHandler(StreamHandler())
+        catalog_logger.setLevel("INFO")
         register_logger.addHandler(StreamHandler())
         register_logger.setLevel("INFO")
     # Set the API key manually here, rather than letting the server do it,
@@ -345,6 +349,12 @@ def serve_catalog(
     log_timestamps: bool = typer.Option(
         False, help="Include timestamps in log output."
     ),
+    verbose: bool = typer.Option(
+        False,
+        "--verbose",
+        "-v",
+        help=("Log details of catalog creation."),
+    ),
 ):
     "Serve a catalog."
     import urllib.parse
@@ -418,6 +428,13 @@ def serve_catalog(
             err=True,
         )
         raise typer.Abort()
+    elif verbose:
+        from logging import StreamHandler
+
+        from tiled.catalog.adapter import logger as catalog_logger
+
+        catalog_logger.addHandler(StreamHandler())
+        catalog_logger.setLevel("INFO")
 
     if write is None:
         typer.echo(