Null bytes (`^@`) in structured logs

[dannywillems]

Preliminary Checks

• This issue is not a duplicate. Before opening a new issue, please search existing issues: https://github.com/MinaProtocol/mina/issues
• This issue is not a question, feature request, RFC, or anything other than a bug report. Please post those things in GitHub Discussions: https://github.com/MinaProtocol/mina/discussions

Description

While investigating #17384, we detected some unexpected unstructured logging information in a devnet node.

{"timestamp":"2025-06-10 23:04:40.330000Z","level":"Debug","source":{"module":"Libp2p_helper.Go.net/identify","location":"(not tracked)"},"message":"libp2p_helper: failed negotiate identify protocol with peer","metadata":{"caller":"identify/id.go:434","go_error":"stream reset","peer":"12D3KooWDHSqgMBza6pnz4VtueaT3vSbJQHbXqgFtzL6A5uttJLx"}}
{"timestamp":"2025-06-10 23:04:40.330000Z","level":"Debug","source":{"module":"Libp2p_helper.Go.net/identify","location":"(not tracked)"},"message":"libp2p_helper: failed to identify 12D3KooWDHSqgMBza6pnz4VtueaT3vSbJQHbXqgFtzL6A5uttJLx: stream reset","metadata":{"caller":"identify/id.go:406"}}
{"timestamp":"2025-06-10 23:04:40.583077Z","level":"Debug","source":{"module":"Mina_lib","location":"File \"src/lib/mina_lib/mina_lib.ml\", line 2431, characters 16-43"},"message":"Current sync status: $status","metadata":{"host":"37.27.237.44","peer_id":"12D3KooWQ2hwPK6kaVFMMe44k3xVCMZWzhNJiRXvM5H1U2ETTDQM","port":10005,"status":"Connecting"}}
{"timestamp":"2025-06-10 23:04:41.583277Z","level":"Debug","source":{"module":"Mina_lib","location":"File \"src/lib/mina_lib/mina_lib.ml\", line 2431, characters 16-43"},"message":"Current sync status: $status","metadata":{"host":"37.27.237.44","peer_id":"12D3KooWQ2hwPK6kaVFMMe44k3xVCMZWzhNJiRXvM5H1U2ETTDQM","port":10005,"status":"Connecting"}}
{"timestamp":"2025-06-10 23:04:42.583635Z","level":"Debug","source":{"module":"Mina_lib","location":"File \"src/lib/mina_lib/mina_lib.ml\", line 2431, characters 16-43"},"message":"Current sync status: $status","metadata":{"host":"37.27.237.44","peer_id":"12D3KooWQ2hwPK6kaVFMMe44k3xVCMZWzhNJiRXvM5H1U2ETTDQM","port":10005,"status":"Connecting"}}

\00 [... ]\00{"timestamp":"2025-06-10 23:11:15.547270Z","level":"Info","source":{"module":"Mina_cli_entrypoint","location":"File \"src/app/cli/src/cli_entrypoint/mina_cli_entrypoint.ml\", line 649, characters 8-19"},"message":"Mina daemon is booting up; built with commit $commit","metadata":{"commit":"a35e44079c01234b2caf92a04f5d3a3f60b2c189"}}
{"timestamp":"2025-06-10 23:11:15.549766Z","level":"Debug","source":{"module":"Mina_lib__Conf_dir","location":"File \"src/lib/mina_lib/conf_dir.ml\", line 21, characters 10-22"},"message":"Created daemon lockfile $lockfile","metadata":{"lockfile":"/root/.mina-config/.mina-lock"}}
{"timestamp":"2025-06-10 23:11:15.549923Z","level":"Debug","source":{"module":"Exit_handlers","location":"File \"src/lib/exit_handlers/exit_handlers.ml\", line 28, characters 2-14"},"message":"Registering async shutdown handler: $description","metadata":{"description":"Remove daemon lockfile"}}

We do not know yet how this happened. The NULL characters prefix a valid structured log.

mina.log

Steps to Reproduce

We do not know.

Expected Result

No NULL character in log.

Actual Result

NULL characters in log.

Daemon version

release/3.1.2

How frequently do you see this issue?

Rarely

What is the impact of this issue on your ability to run a node?

High

Status

See log

Additional information

No response

[dannywillems]

Re NULL characters: it seems that the printf calls go (somtimes? always?) into the log, in an unstructured way.
For instance, while looking at this, I noticed in the log:

Using libp2p keypair private-key password from environment

which comes from:

  let read_exn ?(should_prompt_user = true) ?(should_reask = true) ~which path =
    let read_privkey password = read ~privkey_path:path ~password in
    let%bind result =
      match Sys.getenv env with
      | Some password ->
          (* this function is only called from client commands that can prompt for
             a password, so printing a message, rather than a formatted log, is OK
          *)
          printf "Using %s private-key password from environment variable %s\n"
            which env ;
          read_privkey (lazy (Deferred.return @@ Bytes.of_string password))

in src/lib/secrets/keypair_common.ml:40:.

Therefore, I guess it is worth checking all printf calls.

[dannywillems]

A candidate for printing only null characters would be one printf that simply writes a formatted string.
Candidates I have found for now (using git grep -A1 -B1 printf mina.log are):

mina_lib/mina_lib.ml-250-    Pipe.iter_without_pushback
mina_lib/mina_lib.ml-251-      (Async.Reader.pipe (Process.stdout snark_worker_process))
mina_lib/mina_lib.ml:252:      ~f:(fun s -> printf "%s" s)
mina_lib/mina_lib.ml-253-    |> don't_wait_for ;
--
mina_lib/mina_lib.ml-255-      (Async.Reader.pipe (Process.stderr snark_worker_process))
mina_lib/mina_lib.ml:256:      ~f:(fun s -> printf "%s" s)
mina_lib/mina_lib.ml-257-    |> don't_wait_for ;