Possible memory corruption while logging?

[orf]

While working on #1399, I added a log message to object_access_hook here.

I noticed that the messages appear to be corrupted: the log statement was:

log!("{access} - {class_id} - {object_id} - {sub_id}!");

But the output was:

[2023-11-18 19:17:39.332 GMT] [97347] [65590dd3.17c43]: LOG:  3 - 
oid={#2615, builtin: NamespaceRelationId} - oid=#11 - 0! at character 45

Notice the at character 45 that appears after the terminal !

This appears to be reproducible for me, while running in development or release on MacOS using both pg13 and pg15.

I've added a commit that shows this here: 2744abe

Running

cargo test --features "pg15 cshim proptest" \
           --package pgrx-tests test_callbacks

Outputs:

[2023-11-18 19:36:45.705 GMT] [1998] [6559124d.7ce]: LOG:  statement: BEGIN
[2023-11-18 19:36:45.705 GMT] [1998] [6559124d.7ce]: LOG:  statement: SELECT "tests"."test_callbacks"();
[2023-11-18 19:36:45.708 GMT] [1998] [6559124d.7ce]: LOG:  3 - oid={#2615, builtin: NamespaceRelationId} - oid=#11 - 0! at character 45
[2023-11-18 19:36:45.708 GMT] [1998] [6559124d.7ce]: QUERY:  ALTER table test_hooks_table add column baz boolean
[2023-11-18 19:36:45.708 GMT] [1998] [6559124d.7ce]: STATEMENT:  SELECT "tests"."test_callbacks"();
[2023-11-18 19:36:45.708 GMT] [1998] [6559124d.7ce]: LOG:  3 - oid={#2615, builtin: NamespaceRelationId} - oid=#11 - 0!

I've also noticed this while developing an extension, but it seemed less reproducible.

[orf]

I feel stupid: https://doxygen.postgresql.org/elog_8c.html#a9e478a9364c2ef1778f2d97fdbdf1ea3