Strange output when `print()`ing

[nocturnalwizard]

Background: stock minetestserver, built from source, running via command line (debian/linux)

I'm attempting to debug a digiline component and am using print() to log some info. Every time there is output, there are (seemingly random) server messages (that look like early startup messages repeated) scattered throughout that output in the console. This same behavior documented here has also been observed in other places where I've attempted to print() some output.

Why does this happen, and is there any way to stop it? It's making debugging very difficult.

Code: Select all

...
Digiline linked:        {
  input =     {
      param1 = 15,
      name = "digilines:wire_std_10000000",
      param2 = 0,
    },
  output_rule =     {
      y = 1,
      x = -1,
      z = 0,
    },
  output =     {
      param1 = 14,
      name = "mesecons_luacontroller:luacontroller0000",
      param2 = 0,
    },
  input_rule =     {
      y = -1,
      x = 1,
      z = 0,
    },
}
Digiline did not link:  {
  input =     {
      param1 = 14,
      name = "mod_nodes:electronic_conductor_style_1",
      param2 = 0,
    },
<Eoutput =     {19 17:43:18: [Main] mod "mesecons_doors" has unsatisfied dependencies:  "doors"
<WARNIparam1 = 15,19 17:43:18: [Main] You have unsatisfied dependencies, loading your world anyway. This will become a fatal error in the future.
[MOD] name = "digilines:wire_std_10000000",
<ACTIOparam2 = 0,19 17:43:19: [Main] [MOD]moreblocks: recipe for default:sign_wall_steel production: 3 => 4
<ACT},N> 2023-01-19 17:43:19: [Main] [MOD]moreblocks: recipe for default:paper production: 1 => 4
}ACTION> 2023-01-19 17:43:19: [Main] [MOD]moreblocks: recipe for default:sign_wall_wood production: 3 => 4
Digiline linked:-19 17:4{:19: [Main] Reading authentication data from disk...
  input =     {
      param1 = 14,
      name = "mesecons_luacontroller:luacontroller0000", to resolve node name 'flowers:mushroom_brown'.
      param2 = 0,
    },
  output_rule =     {
      y = -1,
      x = 1,
      z = 0,
    },
  output =     {
      param1 = 15,
      name = "digilines:wire_std_10000000",
      param2 = 0,
    },
  input_rule =     {
      y = 1,
      x = -1,
      z = 0,
    },
}
...

Note the timestamps in the messages that appear within my print() output, e.g. "17:43:18".

The surrounding output (my debug info) happened after 17:47. Very strange.

[Blockhead]

Are you viewing the console over ssh? Is colour working properly? Something with control codes messing up? I'm not sure. I haven't experienced it myself, all my messages always come out in proper order and not interleaved like that.

[LMD]

The standard output (stdout) of a process will practically never be interleaved (barring escape sequences: are you printing unescaped byte strings?). However Minetest's logging goes to stderr (you can confirm this e.g. by running minetest 2> /dev/null, redirecting stderr to the void). You're probably (implicitly) running Minetest with something like minetest 2>&1: Both stderr and stdout ultimately go to the same terminal buffer. This means your debug prints may be interleaved with Minetest's logging.
Options to fix this:

1. Redirect stderr to the void. Do you need Minetest's logs while debugging?
2. Redirect stdout to a file, or use a different method of having two different buffers for stderr and stdout.
3. On the Lua side of things, don't use print, but rather use the io.stderr file handle to output to stderr.
4. Most likely most comfortable: Just replace print with minetest.log.