`pg_test` swallowing mismatching error messages

[workingjubilee]

@willmurnane: if you have a test which you expect to produce an error, so you write #[pg_test(error = "oops")], but it produces a different error, the output from the postgres server is not displayed. if you remove the (error = ...) then the output from the postgres server is displayed.

[BradyBonnette]

Hi @willmurnane

I was taking a look at this issue, and I am not super clear on how to reproduce this. For example, I just chose one test at random, such as this one: https://github.com/tcdi/pgx/blob/develop/pgx-tests/src/tests/array_tests.rs#L269-L273

Then, modified it to look like this:

    #[pg_test(error = "array contains NULLLLLLLLLLLLLLLLLLL")]
    fn test_serde_serialize_array_i32_deny_null() {
        Spi::get_one::<Json>("SELECT serde_serialize_array_i32_deny_null(ARRAY[1,2,3,null, 4])")
            .expect("returned json was null");
    }

Finally, ran that test doing:

cargo test \
  --package pgx-tests \
  --lib \
  --no-default-features \
  --features pg14 -- tests::array_tests::tests::pg_test_serde_serialize_array_i32_deny_null --exact

The output I see is:

...
...
failures:

---- tests::array_tests::tests::pg_test_serde_serialize_array_i32_deny_null stdout ----
installing extension
"/home/brady/.pgx/14.5/pgx-install/bin/postmaster" "-D" "/home/brady/projects/tcdi/pgx/target/pgx-test-data-14" "-h" "localhost" "-p" "32214" "-c" "log_destination=stderr" "-c" "logging_collector=off"
pid=17079
PostgreSQL 14.5 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, 64-bit
[2022-11-04 15:33:52.622 EDT] [17079] [63656920.42b7]: LOG:  starting PostgreSQL 14.5 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, 64-bit
[2022-11-04 15:33:52.622 EDT] [17079] [63656920.42b7]: LOG:  listening on IPv4 address "127.0.0.1", port 32214
[2022-11-04 15:33:52.630 EDT] [17079] [63656920.42b7]: LOG:  listening on Unix socket "/home/brady/.pgx/.s.PGSQL.32214"
[2022-11-04 15:33:52.639 EDT] [17080] [63656920.42b8]: LOG:  database system was shut down at 2022-11-04 15:33:33 EDT
     Creating database pgx_tests
thread 'tests::array_tests::tests::pg_test_serde_serialize_array_i32_deny_null' panicked at 'assertion failed: `(left == right)`
  left: `"array contains NULL"`,
 right: `"array contains NULLLLLLLLLLLLLLLLLLL"`', pgx-tests/src/framework.rs:156:21
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

failures:
    tests::array_tests::tests::pg_test_serde_serialize_array_i32_deny_null

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 250 filtered out; finished in 6.42s

Reverting that test back to it's original state, and re-running the same command above, yields the following output:

running 1 test
    Building extension with features  pg_test pg14
     Running command "cargo" "build" "--features" " pg_test pg14" "--no-default-features" "--message-format=json-render-diagnostics"
  Installing extension
     Copying control file to /home/brady/.pgx/14.5/pgx-install/share/postgresql/extension/pgx_tests.control
     Copying shared library to /home/brady/.pgx/14.5/pgx-install/lib/postgresql/pgx_tests.so
    Finished installing pgx_tests
test tests::array_tests::tests::pg_test_serde_serialize_array_i32_deny_null ... ok

Is this what you were expecting? Were you doing something differently that I should try? Any clarification would be super helpful!

[willmurnane]

Create a function that does a warning message followed by an error. When you have pg_test with an expected error, the warning is swallowed, but with no expected error the warning is displayed as part of the output.

Sorry for terse answer, on my phone. I can make a full test case later.

[BradyBonnette]

Oh, I see.

Using the same test above, are you suggesting something like this is getting swallowed?

    #[pg_test(error = "array contains NULLLLLLLLLLLLL")]
    fn test_serde_serialize_array_i32_deny_null() {
        pgx::warning!("warn message");
        Spi::get_one::<Json>("SELECT serde_serialize_array_i32_deny_null(ARRAY[1,2,3,null, 4])")
            .expect("returned json was null");
    }

Output:

test tests::array_tests::tests::pg_test_serde_serialize_array_i32_deny_null ... FAILED

failures:

---- tests::array_tests::tests::pg_test_serde_serialize_array_i32_deny_null stdout ----
installing extension
"/home/brady/.pgx/14.5/pgx-install/bin/postmaster" "-D" "/home/brady/projects/tcdi/pgx/target/pgx-test-data-14" "-h" "localhost" "-p" "32214" "-c" "log_destination=stderr" "-c" "logging_collector=off"
pid=18482
PostgreSQL 14.5 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, 64-bit
[2022-11-04 15:50:33.596 EDT] [18482] [63656d09.4832]: LOG:  starting PostgreSQL 14.5 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, 64-bit
[2022-11-04 15:50:33.596 EDT] [18482] [63656d09.4832]: LOG:  listening on IPv4 address "127.0.0.1", port 32214
[2022-11-04 15:50:33.605 EDT] [18482] [63656d09.4832]: LOG:  listening on Unix socket "/home/brady/.pgx/.s.PGSQL.32214"
[2022-11-04 15:50:33.613 EDT] [18483] [63656d09.4833]: LOG:  database system was shut down at 2022-11-04 15:40:40 EDT
     Creating database pgx_tests
thread 'tests::array_tests::tests::pg_test_serde_serialize_array_i32_deny_null' panicked at 'assertion failed: `(left == right)`
  left: `"array contains NULL"`,
 right: `"array contains NULLLLLLLLLLLLL"`', pgx-tests/src/framework.rs:156:21
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

failures:
    tests::array_tests::tests::pg_test_serde_serialize_array_i32_deny_null

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 250 filtered out; finished in 6.94s

That is, "warn message" is nowhere to be found?

[willmurnane]

Yes, that’s right. If I recall correctly, passing — —nocapture will show the warning when no error is expected, but not with an expected error.

[BradyBonnette]

Ah yes, I see an issue now. Thanks for the clarification!