Issue with logs formatting after [db-sync-node:Warning] message

[ArturWieczorek]

OS
Your OS: Linux Mint 21.2 Cinnamon
Kernel: 5.15.0-92-generic

Versions

[workstat:cardano.node.basicInfo.version:Notice:5] [2024-02-06 12:52:03.01 UTC] 8.7.3
[workstat:cardano.node.basicInfo.commit:Notice:5] [2024-02-06 12:52:03.01 UTC] a4a8119b59b1fbb9a69c79e1e6900e91292161e7

[db-sync-node:Info:6] [2024-02-06 15:42:55.56 UTC] Version number: 13.2.0.0
[db-sync-node:Info:6] [2024-02-06 15:42:55.56 UTC] Git hash: c5d6b8a1da25fbc7f283a34b07ed75dc747131c6

Build/Install Method
The method you use to build or install cardano-db-sync:
nix

Additional context
Release check for 13.2.0.0

Problem Report

I noticed during sync check on preprod environment that shortly after starting epoch 63 message the warning logs [db-sync-node:Warning] are displaced and not starting as it was in the past - each on a separate new line.

Log snippet and screenshot attached below.

[db-sync-node:Info:64] [2024-02-06 16:11:42.27 UTC] Starting epoch 63
[db-sync-node:Info:64] [2024-02-06 16:11:42.27 UTC] Insert Babbage Block: epoch 63, slot 25574407, block 824961, hash 673fa32353ea5021cb0e3a694d4bfaee201ec9c83118f53f511936fd36fb40b0
[db-sync-node:Warning:64] [2024-02-06 16:11:42.62 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. {"0bd0e5cb74bc80f5e3efee08ff3e655ecfa7d7923ce675c2fb9bd5cf":{"\u0000\u0006C[db-sync-node:Warning:64] [2024-02-06 16:11:42.62 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. {"0bd0e5cb74bc80f5e3efee08ff3e655ecfa7d7923ce675c2fb9bd5cf":{"\u0000\r[db-sync-node:Info:64] [2024-02-06 16:11:42.66 UTC] Insert Babbage Block: epoch 63, slot 25575156, block 825000, hash 38a44fd5b45c2e8f47c27bf2d654f0e2a8a0b6c3116ca754a3b4182114218631
[db-sync-node:Info:72] [2024-02-06 16:11:44.73 UTC] Asynchronously wrote a ledger snapshot to ledger-state/preprod_13_2_0_0_bootstrap_tx_out/25574391-d06e9fe2f2-62.lstate in 2.476885368s.
[db-sync-node:Info:64] [2024-02-06 16:11:47.20 UTC] Inserted 3389 EpochStake for EpochNo 64
[db-sync-node:Info:64] [2024-02-06 16:11:52.20 UTC] Insert Babbage Block: epoch 63, slot 25688668, block 830000, hash 9c846a26c7dd86f9ca271be681fdea69825660c2bd092c704f7bb1a10cf5261b
[db-sync-node:Warning:64] [2024-02-06 16:11:53.82 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. {"b":["[db-sync-node:Warning:64] [2024-02-06 16:11:53.93 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. {"b":["[db-sync-node:Warning:64] [2024-02-06 16:11:53.95 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. {"b":["[db-sync-node:Warning:64] [2024-02-06 16:11:53.95 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. {"json_metadata":{"b":["[db-sync-node:Warning:64] [2024-02-06 16:11:54.08 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. {"b":["[db-sync-node:Warning:64] [2024-02-06 16:11:54.12 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. ["{\"filename\":\"images.jpe","g\",\"data\":[\"[db-sync-node:Info:64] [2024-02-06 16:12:01.59 UTC] Insert Babbage Block: epoch 63, slot 25814413, block 835000, hash 4a92e1d9ac91bfefb45a709366c9d1c1c84781665f0118bfce3bb03d95eb6341
[db-sync-node:Info:64] [2024-02-06 16:12:08.14 UTC] Insert Babbage Block: epoch 63, slot 25940045, block 840000, hash 062b95f1a91e3dafc3f8206ba788feb5ca617c1629c0a166ad2897f8b8e1c989
[db-sync-node:Info:64] [2024-02-06 16:12:08.14 UTC] Pool Offchain metadata fetch: 2 results, 15 fetch errors
[db-sync-node:Info:64] [2024-02-06 16:12:11.09 UTC] Deleted 0 tx_out
[db-sync-node:Info:64] [2024-02-06 16:12:11.33 UTC] Removing old epoch boundary file ledger-state/preprod_13_2_0_0_bootstrap_tx_out/22982389-c9fb79d3b5-56.lstate
[db-sync-node:Info:64] [2024-02-06 16:12:11.33 UTC] Removing 3 orphaned rewards
[db-sync-node:Info:64] [2024-02-06 16:12:11.34 UTC] Validate Epoch Rewards: total rewards that become spendable in epoch 64 are 2648
[db-sync-node:Info:64] [2024-02-06 16:12:11.34 UTC] Persistant SQL Statement Cache size is 432
[db-sync-node:Info:64] [2024-02-06 16:12:11.34 UTC] 

[kderme]

Could this be an issue with the preprod config?

[ArturWieczorek]

Could this be an issue with the preprod config?

Possibly - I will check it again tomorrow and let you know.

[ArturWieczorek]

I synced preprod again and made sure I am using configs from here: https://book.world.dev.cardano.org/env-preprod.html
Warnings are displaced as in the example above.

In the past we were not printing any data for this type of warning so the message looked like that:

[db-sync-node:Warning:74] [2024-02-09 17:18:35.07 UTC] prepareTxMetadata: dropped due to a Unicode NUL character.
[db-sync-node:Warning:74] [2024-02-09 17:18:35.21 UTC] prepareTxMetadata: dropped due to a Unicode NUL character.

also the warning number changed from 74 to 64.

Now, the warning contains also data after this message - like in the example below TEST_USER1\u0000TEST_USER2\u00001696442009\u0000sudhPBw9vM:

[db-sync-node:Warning:64] [2024-02-03 15:27:03.01 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. "TEST_USER1\u0000TEST_USER2\u00001696442009\u0000sudhPBw9vM"

So I guess this might be causing the issue.

[ArturWieczorek]

Found it also on mainnet:

[db-sync-node:Info:67] [2024-02-04 20:06:06.69 UTC] Insert Babbage Block: epoch 369, slot 74337061, block 7890000, hash ce4858e83e85775739a8bc6eff3ff39f5aa284e500b65182cc5cbf7e46f97b0f
[db-sync-node:Info:67] [2024-02-04 20:06:06.69 UTC] Pool Offchain metadata fetch: 92 results, 90 fetch errors
[db-sync-node:Warning:67] [2024-02-04 20:06:51.03 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. {"c5745996830624f79ef3ed8f142dc687e3cb7986f226837de3e1c983":{"\t\u0003[db-sync-node:Warning:67][2024-02-04 20:09:48.12 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. {"\u000c\u0007\u0006[db-sync-node:Warning:67] [2024-02-04 20:09:50.02 UTC] prepareTxMetadata: dropped due to a Unicode NUL character. {"527587636100293ba08ca81faa4c1c3684f448f062f1ef4c462c1e8f":{"\t\u0003[db-sync-node:Info:67] [2024-02-04 20:11:10.73 UTC] Insert Babbage Block: epoch 369, slot 74438678, block 7895000, hash d3d06e1f8b58f5ba83cfc63f03e9d322ce66f045be3b23efd7d6d9332286c6a6
[db-sync-node:Info:67] [2024-02-04 20:14:19.44 UTC] Inserted 8 deposit refund rewards
[db-sync-node:Info:67] [2024-02-04 20:14:19.44 UTC] Removing 2734 orphaned rewards

I found even worse one - I am attaching log file - search for string 52afe68fa7828609dc435636ac53dacff61540d74365e0566c7b0abd.
mainnet_upgrade_13_1_1_2_to_13_2_0_0_logs.txt

Do we want to output such long errors ?

[Cmdv]

could we show just a specific part of the json rather than the whole thing here?

cardano-db-sync/cardano-db-sync/src/Cardano/DbSync/Era/Util.hs

Line 50 in ca2f559

liftIO $ logWarning tracer $ tracePrefix <> ": dropped due to a Unicode NUL character. " <> json