In tests, initialize the database after the logging system

[ctron]

When running tests, we don't have SQLX logs on the tracing/logging system.

The reason for this seems to be fact that we initialize the logging system after the database. The database part however does check the logging system's configuration, and only then enabled database SQL logging.

So either we initialize the logging system first, or we find a way to enable SQL logging when running tests.

[jcrossley3]

Weird, when I set RUST_LOG=none,trustify=debug,sqlx=trace, I see sqlx calls. Are you referring to some other ones?

cargo test qualified_packages_filtering 
...
2024-10-04T15:52:53.758127Z DEBUG purls{query=Query { q: "type=maven", sort: "" } paginated=Paginated { offset: 0, limit: 25 }}: trustify_common::db::query: filtering with: q='type=maven' sort=''    
2024-10-04T15:52:53.765084Z TRACE purls{query=Query { q: "type=maven", sort: "" } paginated=Paginated { offset: 0, limit: 25 }}: sqlx::query: summary="SELECT COUNT(*) AS num_items …" db.statement="\n\nSELECT\n  COUNT(*) AS num_items\nFROM\n  (\n    SELECT\n      \"qualified_purl\".\"id\",\n      \"qualified_purl\".\"versioned_purl_id\",\n      \"qualified_purl\".\"qualifiers\",\n      \"qualified_purl\".\"purl\"\n    FROM\n      \"qualified_purl\"\n      LEFT JOIN \"versioned_purl\" ON \"qualified_purl\".\"versioned_purl_id\" = \"versioned_purl\".\"id\"\n    WHERE\n      \"versioned_purl\".\"base_purl_id\" IN (\n        SELECT\n          \"base_purl\".\"id\"\n        FROM\n          \"base_purl\"\n        WHERE\n          \"base_purl\".\"type\" = $1\n      )\n  ) AS \"sub_query\"\n" rows_affected=0 rows_returned=1 elapsed=4.229869ms elapsed_secs=0.004229869
2024-10-04T15:52:53.768737Z TRACE purls{query=Query { q: "type=maven", sort: "" } paginated=Paginated { offset: 0, limit: 25 }}: sqlx::query: summary="SELECT \"qualified_purl\".\"id\", \"qualified_purl\".\"versioned_purl_id\", \"qualified_purl\".\"qualifiers\", …" db.statement="\n\nSELECT\n  \"qualified_purl\".\"id\",\n  \"qualified_purl\".\"versioned_purl_id\",\n  \"qualified_purl\".\"qualifiers\",\n  \"qualified_purl\".\"purl\"\nFROM\n  \"qualified_purl\"\n  LEFT JOIN \"versioned_purl\" ON \"qualified_purl\".\"versioned_purl_id\" = \"versioned_purl\".\"id\"\nWHERE\n  \"versioned_purl\".\"base_purl_id\" IN (\n    SELECT\n      \"base_purl\".\"id\"\n    FROM\n      \"base_purl\"\n    WHERE\n      \"base_purl\".\"type\" = $1\n  )\nLIMIT\n  $2\n" rows_affected=3 rows_returned=3 elapsed=1.983089ms elapsed_secs=0.001983089
2024-10-04T15:52:53.770971Z TRACE purls{query=Query { q: "type=maven", sort: "" } paginated=Paginated { offset: 0, limit: 25 }}: sqlx::query: summary="SELECT \"versioned_purl\".\"id\", \"versioned_purl\".\"base_purl_id\", \"versioned_purl\".\"version\" …" db.statement="\n\nSELECT\n  \"versioned_purl\".\"id\",\n  \"versioned_purl\".\"base_purl_id\",\n  \"versioned_purl\".\"version\"\nFROM\n  \"versioned_purl\"\nWHERE\n  \"versioned_purl\".\"id\" IN ($1, $2, $3)\n" rows_affected=2 rows_returned=2 elapsed=1.01319ms elapsed_secs=0.00101319
2024-10-04T15:52:53.773593Z TRACE purls{query=Query { q: "type=maven", sort: "" } paginated=Paginated { offset: 0, limit: 25 }}: sqlx::query: summary="SELECT \"base_purl\".\"id\", \"base_purl\".\"type\", \"base_purl\".\"namespace\", …" db.statement="\n\nSELECT\n  \"base_purl\".\"id\",\n  \"base_purl\".\"type\",\n  \"base_purl\".\"namespace\",\n  \"base_purl\".\"name\"\nFROM\n  \"base_purl\"\n  INNER JOIN \"versioned_purl\" ON \"versioned_purl\".\"base_purl_id\" = \"base_purl\".\"id\"\nWHERE\n  \"versioned_purl\".\"id\" = $1\nLIMIT\n  $2\n" rows_affected=0 rows_returned=1 elapsed=1.216304ms elapsed_secs=0.001216304
2024-10-04T15:52:53.776078Z TRACE purls{query=Query { q: "type=maven", sort: "" } paginated=Paginated { offset: 0, limit: 25 }}: sqlx::query: summary="SELECT \"base_purl\".\"id\", \"base_purl\".\"type\", \"base_purl\".\"namespace\", …" db.statement="\n\nSELECT\n  \"base_purl\".\"id\",\n  \"base_purl\".\"type\",\n  \"base_purl\".\"namespace\",\n  \"base_purl\".\"name\"\nFROM\n  \"base_purl\"\n  INNER JOIN \"versioned_purl\" ON \"versioned_purl\".\"base_purl_id\" = \"base_purl\".\"id\"\nWHERE\n  \"versioned_purl\".\"id\" = $1\nLIMIT\n  $2\n" rows_affected=0 rows_returned=1 elapsed=1.22487ms elapsed_secs=0.00122487
2024-10-04T15:52:53.778512Z TRACE purls{query=Query { q: "type=maven", sort: "" } paginated=Paginated { offset: 0, limit: 25 }}: sqlx::query: summary="SELECT \"base_purl\".\"id\", \"base_purl\".\"type\", \"base_purl\".\"namespace\", …" db.statement="\n\nSELECT\n  \"base_purl\".\"id\",\n  \"base_purl\".\"type\",\n  \"base_purl\".\"namespace\",\n  \"base_purl\".\"name\"\nFROM\n  \"base_purl\"\n  INNER JOIN \"versioned_purl\" ON \"versioned_purl\".\"base_purl_id\" = \"base_purl\".\"id\"\nWHERE\n  \"versioned_purl\".\"id\" = $1\nLIMIT\n  $2\n" rows_affected=0 rows_returned=1 elapsed=1.096435ms elapsed_secs=0.001096435
test purl::endpoints::test::qualified_packages_filtering ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 92 filtered out; finished in 4.45s

[ctron]

You're right, I am actually not missing the sqlx stuff, but the sea_orm logs, which seem easier to read for me:

2024-10-07T07:11:47.759210Z DEBUG ThreadId(01) run: sea_orm::driver::sqlx_postgres: SELECT "importer"."name", "importer"."revision", "importer"."state", "importer"."last_change", "importer"."last_success", "importer"."last_run", "importer"."last_error", "importer"."progress_current", "importer"."progress_total", "importer"."continuation", "importer"."configuration" FROM "importer"
2024-10-07T07:11:47.762832Z TRACE ThreadId(01) run: sqlx::query: summary="SELECT \"importer\".\"name\", \"importer\".\"revision\", \"importer\".\"state\", …" db.statement="\n\nSELECT\n  \"importer\".\"name\",\n  \"importer\".\"revision\",\n  \"importer\".\"state\",\n  \"importer\".\"last_change\",\n  \"importer\".\"last_success\",\n  \"importer\".\"last_run\",\n  \"importer\".\"last_error\",\n  \"importer\".\"progress_current\",\n  \"importer\".\"progress_total\",\n  \"importer\".\"continuation\",\n  \"importer\".\"configuration\"\nFROM\n  \"importer\"\n" rows_affected=12 rows_returned=12 elapsed=387.787µs elapsed_secs=0.000387787

[jcrossley3]

Interesting. I assume by "missing", you mean "seeing". I agree those are easier to read, and I don't see them when RUST_LOG=none,sea_orm=debug, as I would expect.

[ctron]

🤦 I meant "not missing". But yes.