Godot output/debug console is out of order when using RPCs and/or multiple clients

TheYellowArchitect commented 1 year ago

Godot version

4.1 stable

System information

Godot v4.1.stable - Artix Linux #1 SMP PREEMPT_DYNAMIC Thu, 03 Nov 2022 21:10:08 +0000 - Vulkan (Forward+) - dedicated NVIDIA GeForce GTX 1050 Ti (nvidia; 520.56.06) - AMD Ryzen 5 2600 Six-Core Processor (12 Threads)

Issue description

Synopsis: I have X message before I send an RPC. And a different print message when I receive it. Yet, in the console log, I first receive the RPC receival print message before X message.

As for details. Basically, you cannot have a proper print order, because all clients dont print in the exact logical order the code ran. I added timestamps just in case, but they are futile since the timestamp of all clients don't start in the exact same frame. So if you run

func _enter_tree() -> void:
    print("Started at timestamp: ", Time.get_ticks_usec())

with 3 debug clients, all 3 timestamps are different.

The MRP also supports 3 clients ofc. 3 clients instead of 2 is a guarantee to have the debug log scrambled.

Video-explanation for those who don't want to run the MRP

tl;dr: I cannot read the debug log linearly with multiple clients.

Steps to reproduce

Basically create an RPC from host to client to host. Print messages before and after RPCs with the multiplayer ID. Chances are you don't even need a more complex scenario (like this MRP)

Minimal reproduction project

debug-log-out-of-order.zip

Calinou commented 1 year ago

Related to https://github.com/godotengine/godot-proposals/issues/3357.

I don't think we can do anything about this, other than implementing support for split output panels or adding a prefix before every instance's message.

TheYellowArchitect commented 1 year ago

I don't understand how that is related. This issue is not about showing explicitly the different ID. The problem is that messages are out of order, and the above won't solve that.

So, right before client2 sends an RPC to the server, he prints message X. When server receives the above RPC, he prints message Y.

Yet, on the console output window, the message Y is sometimes before X.

Faless commented 1 year ago

I agree with @Calinou the main issue is that we should not mix all the logs together (I had been arguing this since the feature was implemented, but there was resistance to splitting the logs at the time).

We can't really guarantee this kind of ordering when running multiple instances, as each instance is independent from each other, each with a different connected stream to the debugger.

I don't think there is any way to guarantee that the OS will ensure ordering across the different TCP debugger streams.

Think about this flow (I will assume a single core for simplicity, but the concept is the same, i.e. "race condition" across different processes):

Editor process the debuggers in a loop, starting from the Server stream.
Editor finishes processing the Server stream, is moving to the Client stream.
A context switch happens, the Server instance is now active.
Server writes the log on the debugger stream, then send the RPC.
A context switch happens, the Client instance is now active.
Client process the RPC, then writes the log to the debugger stream.
A Context switch happens, the Editor instance is now active.
Editor resumes from where it left off, i.e. processing the Client stream.
Editor prints the Client log as read from the Client stream (i.e. before reading the Server log).

TheYellowArchitect commented 1 year ago

You are right, I didn't think that the RPCs' arrival is also determined by the OS. I thought that basically all playable instances are independent and running on a seperate thread, and that they write on output log instantly on arrival (localhost so no latency) but you are right, there are many variables like single/multi core.

Since the log cannot be chronologically linear, @Calinou is right, the problem is solved if different playable instances are made distinct in the console output, e.g. with a color tag at the front or a digit or a filter too, that UI part is negligible compared to the rest

godotengine / godot