search

trustification / trustify

Apache License 2.0
10 stars 19 forks source link

In tests, initialize the database after the logging system #894

Open ctron opened 3 days ago

ctron commented 3 days ago

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 commented 3 days ago

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 commented 19 hours ago

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 commented 13 hours ago

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 commented 13 hours ago

:facepalm: I meant "not missing". But yes.