Give developers more control over logging prints/warns/errors etc.

unrealest commented 1 year ago

Describe the project you are working on

Not really project specific, but I wanted to make a developer console to both log errors and give players more customization over the game.

Describe the problem or limitation you are having in your project

I cannot see any prints, warns, or errors from the output in GDScript, which makes making a developer console nearly impossible, if not, impractical.

Describe the feature / enhancement and how it helps to overcome the problem or limitation

Add some signals for when an error, warning or print is produced. Have some parameters for important information, such as the type of output, and the content (eg. print('Hello, world!') would produce 'Hello, world!' as the content).

I am not sure where the signals could be placed in a way that is consistent with the rest of Godot, perhaps a node called "LogListener" or such.

Describe how your proposal will work, with code, pseudo-code, mock-ups, and/or diagrams

I'll go with my way, something like this:

@onready var log_listener = $LogListener

func _ready():
    var listener_function = func(content, type)
        # This would go in an endless loop, but you get the point lol
        print('Printed: '+content)

    log_listener.logged.connect(listener_function)

If this enhancement will not be used often, can it be worked around with a few lines of script?

No, as there is no way of doing this in GDScript as far as I know.

Is there a reason why this should be core and not an add-on in the asset library?

This is something that can probably only be implemented directly inside the engine.

Zireael07 commented 1 year ago

IMHO a bad idea - signals are bad for performance and logging can already be bad for performance (Some people output hundreds or thousands of errors per FRAME)

KoBeWi commented 1 year ago

Excessive printing is already quite laggy.

TheDuriel commented 1 year ago

I have been using my own Logging Autoload for years now. Wrote it in one hour.

So I would say that > If this enhancement will not be used often, can it be worked around with a few lines of script? Is absolutely true.

If you replace your print and exception calls with Log.error(who, what, message) you can do any further signaling and logic right then and there. Without losing anything offered by the engines own functions, which you can still call within your own logging class. (Basically. Instead of "how can I react to the engine doing a thing when I do a thing." Think about how you can do a thing, and then the engine acts accordingly.)

Here is an example https://gist.github.com/TheDuriel/6c3c05bbe7b4ec07bf21194fe5563ba1 (This is from before Godot automatically logged stuff to disk, and is definitely not the prettiest. Does include a handy ingame log viewer though.)

Zireael07 commented 1 year ago

I've seen at least two other logging autoloads out there (and I'm personally using a third of my own LOL)

AFAIK none of those use signals, though

Calinou commented 1 year ago

ctrlraul commented 1 year ago

I have been using my own Logging Autoload for years now. Wrote it in one hour.

So I would say that > If this enhancement will not be used often, can it be worked around with a few lines of script? Is absolutely true.

If you replace your print and exception calls with Log.error(who, what, message) you can do any further signaling and logic right then and there. Without losing anything offered by the engines own functions, which you can still call within your own logging class. (Basically. Instead of "how can I react to the engine doing a thing when I do a thing." Think about how you can do a thing, and then the engine acts accordingly.)

Here is an example https://gist.github.com/TheDuriel/6c3c05bbe7b4ec07bf21194fe5563ba1 (This is from before Godot automatically logged stuff to disk, and is definitely not the prettiest. Does include a handy ingame log viewer though.)

That is a nice piece of code you shared but misses the point quite entirely, as it doesn't show errors not logged by the programmers themselves.

I don't get the argument that it is too laggy to log too much stuff, if your game outputs so many logs that it can hurt the performance then don't have an in-game debugger? Use it if it suits your use case.

This would be enormously useful, #536 was marked as completed however from what I can see (and I would love to be corrected) we can only read stdin, not stdout, which is not what was requested at all.

Also before anyone points out again, there is no need for the engine to keep the entire stdout in memory, just use signals for when a line is printed.

Calinou commented 1 year ago

This would be enormously useful, https://github.com/godotengine/godot-proposals/issues/536 was marked as completed however from what I can see (and I would love to be corrected) we can only read stdin, not stdout, which is not what was requested at all.

It was not completed – the proposal was closed before GitHub allowed to close issues while distinguishing "completed" from "invalid/duplicate/not planned".

VapidLinus commented 1 year ago

I'm making a developer console as well where I need to see the log output. Here's a workaround I found that works in C# on Windows:

    [Export] private RichTextLabel feed;

    private FileStream logStream;
    private StreamReader logReader;

    public override void _EnterTree()
    {
        var path = GlobalizePath(GetSetting("debug/file_logging/log_path").AsString());
        logStream = new FileStream(path, FileMode.Open, FileAccess.Read, FileShare.ReadWrite);
        logReader = new StreamReader(logStream);

        GD.PushError("Sample GD.PushError");
        GD.PushWarning("Sample GD.PushWarning");
    }

    public override void _ExitTree()
    {
        logReader.Dispose();
        logStream.Dispose();
    }

    public override void _Process(double delta)
    {
        while (!logReader.EndOfStream)
        {
            // Read the new line added to the feed.
            var line = logReader.ReadLine();
            if (line is null) continue;

            // Determine color based on type
            bool isUserError = line.StartsWith("USER ERROR:");
            bool isUserWarning = !isUserError && line.StartsWith("USER WARNING:");
            var color = isUserError ? Colors.Red : isUserWarning ? Colors.Orange : Colors.Gray;

            // Write to rich text box
            feed.PushMono();
            feed.PushColor(color);
            feed.Newline();
            feed.AppendText(line);
            feed.Pop();
            feed.Pop();
        }
    }

It's far from perfect and has some limitations but it's good enough for me for now. I haven't tested in gdscript nor non-windows platforms but it's possible it might work there too.

Update: This method fails to read output on exported builds and is inconvenient when doing local multiplayer development and running two copies at once as everything you log is outputted on all running instances :/

DavidSM64 commented 1 year ago

I am playing around with VR in Godot, and having an in-game way to see print messages would be very handy for testing purposes. I made a proof-of-concept for adding signals to the print functions. It does have some flaws (I mention them at the end), but this should be easy to implement. This is my first time working with the Godot code, so I probably missed some obvious things. Feel free to criticize. :)

The idea I had was to add 3 signals into the OS object:

on_print(line : String)
on_print_rich(line : String)
on_print_error(line : String)

In the gdscript file you can simply do:

OS.on_print.connect(_my_print_func)
OS.on_print_rich.connect(_my_print_rich_func)
OS.on_print_error.connect(_my_print_error_func)

These only require modifying 3 files: core/core_bind.cpp, core/os/os.h, and core/os/os.cpp.

I am taking advantage of the already existing OS::print, OS::print_rich, and OS::printerr functions in the os file that is used for the logger.

In os.cpp I added:

// Function pointer that will call a function to emit the signal.
void (*print_signal_function)(OS::PrintSignalFunction funcType, const char *p_format, va_list p_list) = nullptr;

// public function that sets the function pointer. Used in core_bind.cpp.
void OS::set_print_signal_callback(void (*pPrintFunction)(OS::PrintSignalFunction funcType, const char *p_format, va_list p_list)) {
    print_signal_function = pPrintFunction;
}

// Used to prevent infinite recursion from prints in the callback.
bool isExecutingPrintSignal = false;

// Make a couple safety checks before running the callback function.
void _run_print_signal(OS::PrintSignalFunction funcType, const char *p_format, va_list p_list) {
    // Make sure print_signal_function is defined
    if (!print_signal_function) {
        return; 
    }
    // Make sure we aren't doing infinite recursion. (Very bad; would not recommend!)
    if(isExecutingPrintSignal) {
        return; 
    }

    // TODO: This is probably not thread safe. Might need to add a mutex.
    isExecutingPrintSignal = true;
    print_signal_function(funcType, p_format, p_list);
    isExecutingPrintSignal = false;
}

void OS::print(const char *p_format, ...) {
    ... // Shortened for brevity
    va_list argp;
    va_start(argp, p_format);

    // Added this function that will call a function in core_bind.cpp
    // For OS::print_rich use `SIGNAL_FUNCTION_PRINT_RICH`, and OS::printerr use `SIGNAL_FUNCTION_PRINT_ERROR`
    _run_print_signal(SIGNAL_FUNCTION_PRINT, p_format, argp);

    if (_logger) {
    ... // Shortened for brevity
}

os.h exposes the set_print_signal_callback function and also the PrintSignalFunction enum I'm using to differentiate between the signal types.

public:
    enum PrintSignalFunction {
        SIGNAL_FUNCTION_PRINT,
        SIGNAL_FUNCTION_PRINT_RICH,
        SIGNAL_FUNCTION_PRINT_ERROR
    };

    void set_print_signal_callback(void (*pPrintFunction)(PrintSignalFunction funcType, const char *p_format, va_list p_list));

In core_bind.cpp I added some functions to the OS section that deal with processing the varargs and emitting the signals.

// Converts varargs into a string variant. Copied most of this code from vlog() in core/io/logger.cpp
String _get_varargs_as_string_variant(const char *p_format, va_list p_list) {
    const int static_buf_size = 512;
    char static_buf[static_buf_size];
    char *buf = static_buf;
    va_list list_copy;
    va_copy(list_copy, p_list);
    int len = vsnprintf(buf, static_buf_size, p_format, p_list);
    if (len >= static_buf_size) {
        buf = (char *)Memory::alloc_static(len + 1);
        vsnprintf(buf, len + 1, p_format, list_copy);
    }
    String out(buf);
    if (len >= static_buf_size) {
        Memory::free_static(buf);
    }
    return out;
}

// Check if the signal has any connections first before doing the expensive stuff.
static void _emit_print_signal_if_it_has_any_connections(StringName signalName, const char *p_format, va_list p_list) {
    // I'm making an assumption that get_signal_connection_list() isn't too expensive to run for every print.
    // Would be nice if signals kept a variable for the number of current connections it has. :)
    List<Object::Connection> p_connections;
    OS::get_singleton()->get_signal_connection_list(signalName, &p_connections);
    if (p_connections.size() == 0) {
        // No connections found, so we'll just exit.
        return;
    }
    // It has atleast one connection, so emit it!
    OS::get_singleton()->emit_signal(signalName, _get_varargs_as_string_variant(p_format, p_list));
}

// Gets called from os.cpp print methods
static void _on_print_callback(::OS::PrintSignalFunction funcType, const char *p_format, va_list p_list) {
    switch (funcType) {
        case ::OS::SIGNAL_FUNCTION_PRINT:
            _emit_print_signal_if_it_has_any_connections(StringName("on_print"), p_format, p_list);
            break;
        case ::OS::SIGNAL_FUNCTION_PRINT_RICH:
            _emit_print_signal_if_it_has_any_connections(StringName("on_print_rich"), p_format, p_list);
            break;
        case ::OS::SIGNAL_FUNCTION_PRINT_ERROR:
            _emit_print_signal_if_it_has_any_connections(StringName("on_print_error"), p_format, p_list);
            break;
    }
}

// At the bottom of _bind_methods I added the 3 signals and setup the callback for os.cpp.
void OS::_bind_methods() {
    ... // Shortened for brevity

    // Setup signals for text that gets printed.
    ADD_SIGNAL(MethodInfo("on_print", PropertyInfo(Variant::STRING, "line")));
    ADD_SIGNAL(MethodInfo("on_print_rich", PropertyInfo(Variant::STRING, "line")));
    ADD_SIGNAL(MethodInfo("on_print_error", PropertyInfo(Variant::STRING, "line")));

    // Setup callback for the signal.
    ::OS::get_singleton()->set_print_signal_callback(&_on_print_callback);
}

That is it. Here is a sample script using a label3d to make the most basic console:

extends Label3D

const MAX_NUM_LINES = 10

func _ready():
    # All the signals take the same arguments, so you can assign the same function to all of them.
    OS.on_print.connect(_add_text_to_console)
    OS.on_print_rich.connect(_add_text_to_console)
    OS.on_print_error.connect(_add_text_to_console)
    text = '' # Console should start empty.

# Finds the index of a line in the console text.
# Returns -1 if n is out of bounds.
func _find_nth_line(n: int) -> int:
    var numLines = text.count('\n')
    if n < 0 or n >= numLines:
        return -1
    elif n == 0:
        return 0
    var curLineIndex : int = 0
    while curLineIndex != -1:
        n -= 1
        if n < 0:
            break
        curLineIndex = text.find('\n', curLineIndex) + 1
    return curLineIndex

# Removes older lines if the maximum number has been reached.
func _limit_text_to_n_lines():
    var numLines = text.count('\n')
    if numLines < MAX_NUM_LINES:
        return
    var newStart : int = _find_nth_line(numLines - MAX_NUM_LINES)
    text = text.substr(newStart)

func _add_text_to_console(line : String):
    text += line
    _limit_text_to_n_lines()

################################################################################

# Repeated prints, just for quick testing.
var delay : float = 0
var nextPrint : int = 0
func _physics_process(delta):
    delay += delta
    if delay < 0.4:
        return
    delay = 0.0
    # Cycle normal prints, then rich prints, then error prints, repeat.
    match nextPrint:
        0:
            print("This is some normal text")
        1:
            print_rich("[color=yellow]This [b]is[/b] some rich text![/color]")
        2:
            printerr("This is an error!!!")
    nextPrint = (nextPrint + 1) % 3

################################################################################

Result:

Flaws/Issues with the code

1.) The code, as written, is currently not thread safe. See the _run_print_signal function in the os.cpp section above. 2.) Does not work with configuration warnings. I don't think godot has a print_warning either? 3.) All the text is preprocessed before the signal is emitted, so the only information you get is a string. 4.) For print_rich, you'll have to make logic for the ANSI escape codes. 5.) I'm making the assumption that this shouldn't greatly affect performance. The signal itself will not be emitted if there are no connections.

godotengine / godot-proposals