godotengine / godot

Godot Engine – Multi-platform 2D and 3D game engine
https://godotengine.org
MIT License
86.88k stars 19.45k forks source link

PackedByteArray decode issue #84340

Open tlloancy opened 8 months ago

tlloancy commented 8 months ago

Godot version

4.1.2

System information

Windows 10

Issue description

when this

[71, 69, 84, 32, 47, 32, 72, 84, 84, 80, 47, 49, 46, 49, 13, 10, 72, 111, 115, 116, 58, 32, 49, 55, 50, 46, 49, 48, 52, 46, 50, 53, 49, 46, 50, 49, 49, 58, 57, 48, 56, 48, 13, 10, 85, 112, 103, 114, 97, 100, 101, 58, 32, 119, 101, 98, 115, 111, 99, 107, 101, 116, 13, 10, 67, 111, 110, 110, 101, 99, 116, 105, 111, 110, 58, 32, 85, 112, 103, 114, 97, 100, 101, 13, 10, 83, 101, 99, 45, 87, 101, 98, 83, 111, 99, 107, 101, 116, 45, 75, 101, 121, 58, 32, 48, 55, 57, 67, 113, 122, 72, 113, 102, 72, 66, 118, 79, 87, 47, 104, 118, 110, 119, 51, 86, 119, 61, 61, 13, 10, 83, 101, 99, 45, 87, 101, 98, 83, 111, 99, 107, 101, 116, 45, 86, 101, 114, 115, 105, 111, 110, 58, 32, 49, 51, 13, 10, 13, 10]

is given to bytes_to_var i get this

ERROR: Condition "(type & 0xFF) >= Variant::VARIANT_MAX" is true. Returning: ERR_INVALID_DATA
   at: decode_variant (core/io/marshalls.cpp:106)

and when this is nested in an array like this

[[71, 69, 84, 32, 47, 32, 72, 84, 84, 80, 47, 49, 46, 49, 13, 10, 72, 111, 115, 116, 58, 32, 49, 55, 50, 46, 49, 48, 52, 46, 50, 53, 49, 46, 50, 49, 49, 58, 57, 48, 56, 48, 13, 10, 85, 112, 103, 114, 97, 100, 101, 58, 32, 119, 101, 98, 115, 111, 99, 107, 101, 116, 13, 10, 67, 111, 110, 110, 101, 99, 116, 105, 111, 110, 58, 32, 85, 112, 103, 114, 97, 100, 101, 13, 10, 83, 101, 99, 45, 87, 101, 98, 83, 111, 99, 107, 101, 116, 45, 75, 101, 121, 58, 32, 48, 55, 57, 67, 113, 122, 72, 113, 102, 72, 66, 118, 79, 87, 47, 104, 118, 110, 119, 51, 86, 119, 61, 61, 13, 10, 83, 101, 99, 45, 87, 101, 98, 83, 111, 99, 107, 101, 116, 45, 86, 101, 114, 115, 105, 111, 110, 58, 32, 49, 51, 13, 10, 13, 10]]

i get

ERROR: Condition "len < 4" is true. Returning: ERR_INVALID_DATA
   at: decode_variant (core/io/marshalls.cpp:102)

don't know what to do

Steps to reproduce

bytes_to_var([1, 2, 3, ...])
ERROR: Condition "(type & 0xFF) >= Variant::VARIANT_MAX" is true
bytes_to_var([[1, 2, 3, ...]])
ERROR: Condition "len < 4" is true

[edit] ~~an array with 3 elem max will lead to len < 4 error. 3+ is VARIANT_MAX error.~~ that's so random

Minimal reproduction project

N/A

timothyqiu commented 8 months ago

bytes_to_var() is meant to decode bytes from var_to_bytes(). It's using a specific binary format for Godot variants.

To decode arbitrary bytes, use decode_*() methods in PackedByteArray.

tlloancy commented 8 months ago

Is it built the same as bytes2var() and var2bytes() ?

AThousandShips commented 8 months ago

What is the data from? How did you generate it?

The steps to reproduce will obviously fail as the input is not valid data, did you mean to provide the data given above?

tlloancy commented 8 months ago

error based on this work that i try to port to godot version 4 Messages MatchMakerServer

AThousandShips commented 8 months ago

Are you trying to get data generated in Godot 3 into Godot 4? That's not supported, binary compatibility is not supported, see:

If not please explain what the data is coming from, is it from var_to_bytes?

tlloancy commented 8 months ago

It is var_to_bytes but since websocketserver doesnt exist anymore, i replaced that by TCPServer.

And while i still can have peers to connect to it and the connection be accepted and open on server side, on client side (websocketpeer), get_ready_state() keep staying on connecting.

So i thought maybe streampeerTCP gathered with take_connection() was not enough, with its methods get_data() and put_data(), to communicate with the client. So i started thinking about creating a new websocketpeer and accept stream, and communicate with this websocketpeer instead of streampeertcp, but when i do that, streampeerTCP disconnects immediately.

It made sense that if get_data() didn't return PackedByteArray as get_packet() maybe i had a clue why the wrong data was sent to bytes_to_var(), and that i had to use websocketpeer instead of streampeerTCP to communicate with client peer.

But now i'm confused. Why can i stream packets with streampeerTCP AND Websocketpeer ? What's the difference.

Messages are sent encoded with method var_to_bytes() and decoded with bytes_to_var() and both server and client are godot 4

AThousandShips commented 8 months ago

Might well be related to the data encoding, but without the actual code I can't say much more

tlloancy commented 8 months ago

do you wante me to show it

AThousandShips commented 8 months ago

Otherwise there's nothing that can be done, unless you can show the data you're trying to decide is valid there's no bug here

AThousandShips commented 8 months ago

But it sounds like you might be trying to access raw data which has extra encoding, try using the get_var directly instead

tlloancy commented 8 months ago
extends Node

@export var match_size: int

const PORT = 9080
var _server = TCPServer.new()
var spTCP
var _connected_players = {}
var _match_queue = []

func _logger_coroutine():
    while(true):
        await get_tree().create_timer(3).timeout

        var p = ""
        for player in _connected_players.keys():
            p += str(player) + " "

        var m = ""
        for id in _match_queue:
            m += str(id) + " "

        printt("Connected:   " + p)
        printt("Match queue: " + m + "\n")

func _ready():
    print("Starting server...")

    var err = _server.listen(PORT)
    if err != OK:
        print("Unable to start server")
        set_process(false)

    _logger_coroutine()

func _connected(id, proto):
    print("hiiiiiihhooouu")
    print("Client %d connected with protocol: %s" % [id.get_instance_id(), proto])
    _connected_players[id] = [] # match queue
    _match_queue.append(id)

    var message = Message.new()
    message.server_login = true
    message.content = id
    id.put_data(message.get_raw())

func _match_size():
    pass

func create_new_match(spTCP):
    var new_match = []
    for i in range(match_size):
        new_match.append(_match_queue[i])

    for i in range(match_size):
        var message = Message.new()
        message.match_start = true
        message.content = new_match
        spTCP.put_data(message.get_raw())
        _match_queue.remove_at(0)

    for i in range(new_match.size()):
        _connected_players[new_match[i]] = new_match

func remove_player_from_connections(id):
    if _match_queue.has(id):
        _match_queue.erase(id)

    if _connected_players.has(id):
        if _connected_players[id] != null:
            _connected_players[id].erase(id)
        _connected_players.erase(id)

func _close_request(id, code, reason):
    print("Client %d disconnecting with code: %d, reason: %s" % [id.get_instance_id(), code, reason])

    var message = Message.new()
    message.disconnected_closed = true
    message.content = id

    for player_id in _connected_players[id]:
        if (player_id != id):
            id.put_data(message.get_raw())

    remove_player_from_connections(id)

func _disconnected(id, was_clean = false):
    print("Client %d disconnected, clean: %s" % [id.get_instance_id(), str(was_clean)])

    var message = Message.new()
    message.disconnected_disconnected = true
    message.content = id

    for player_id in _connected_players[id]:
        if (player_id != id):
            id.put_data(message.get_raw())

    remove_player_from_connections(id)

func _on_data(buf, id, ids):
    var message = Message.new()
    print("j ai rentré quand meme!")
    print(buf)
    var res = id.get_packet()
    #var res = id.get_data(buf)
    print(res)
    message.from_raw(res)
    print("un")
    for player_id in _connected_players[ids]:
        print(ids)
        if (player_id != ids || (player_id == ids && message.is_echo)):
            print(player_id)
            id.put_packet(message.get_raw())
    print("quatro")

func _process(delta):
    if _server.is_connection_available():
        spTCP = _server.take_connection()
        _connected(spTCP, "TCP")

    for _conn in _connected_players.keys():
        _conn.poll()
        var buf = 0
        var state = _conn.get_status()
        if state == StreamPeerTCP.STATUS_CONNECTED:
            var wsp = WebSocketPeer.new()
            wsp.accept_stream(spTCP)
            wsp.poll()
            var status = wsp.get_ready_state()
            if status == WebSocketPeer.STATE_OPEN:
                while wsp.get_available_packet_count():
                    _on_data(buf, wsp, _conn)
            #while true:
            #   buf = _conn.get_available_bytes()
            #   if buf <= 0:
            #       break
            #   _on_data(buf, _conn)
        elif state == StreamPeerTCP.STATUS_CONNECTING:
            pass
        elif state == StreamPeerTCP.STATUS_NONE:
            _disconnected(_conn)
        else: # STATUS_ERROR
            _close_request(_conn, 00, "ERROR")
            pass

        if (_match_queue.size() >= match_size):
            create_new_match(_conn)
tlloancy commented 8 months ago

this is the matchmaker server for version 4

tlloancy commented 8 months ago
class_name Message

const SERVER_LOGIN = 1
const MATCH_START = 2
const IS_ECHO = 4
const DISCONNECTED_CLOSED = 8
const DISCONNECTED_DISCONNECTED = 16
const MATCH_SIZE = 32

const _BYTE_MASK = 255

var server_login : bool
var match_start : bool
var is_echo : bool
var disconnected_closed : bool
var disconnected_disconnected : bool
var match_size : int

var content

func get_raw() -> PackedByteArray:
    var message = PackedByteArray()

    var byte = 0
    byte = set_bit(byte, SERVER_LOGIN, server_login)
    byte = set_bit(byte, IS_ECHO, is_echo)
    byte = set_bit(byte, MATCH_START, match_start)
    byte = set_bit(byte, DISCONNECTED_CLOSED, disconnected_closed)
    byte = set_bit(byte, DISCONNECTED_DISCONNECTED, disconnected_disconnected)
    byte = set_bit(byte, MATCH_SIZE, match_size)

    message.append(byte)
    message.append_array(var_to_bytes_with_objects(content))

    return message

func from_raw(arr):
    print(arr)
    var flags = arr[0]
    print(arr)
    server_login = get_bit(flags, SERVER_LOGIN)
    print(arr)
    is_echo = get_bit(flags, IS_ECHO)
    match_start = get_bit(flags, MATCH_START)
    disconnected_closed = get_bit(flags, DISCONNECTED_CLOSED)
    disconnected_disconnected = get_bit(flags, DISCONNECTED_DISCONNECTED)
    match_size = get_bit(flags, MATCH_SIZE)
    print(arr)
    content = null
    print("allo")
    print(arr)
    if (arr.size() > 1):
        print("alloallo")
        print(arr)
        print("OW")
        print(arr.slice(1, -1))
        print("OOOOWW")
        print(arr.slice(1, arr.size())[0])
        print("OOOOOOOOOOOWWWWWWWW")
        print(arr.slice(1, arr.size() - 1))
        content = bytes_to_var_with_objects(arr.slice(1, arr.size())[0])
        print("alloalloallo")

func get_bit(byte : int, flag : int) -> bool:
    return byte & flag == flag

func set_bit(byte : int, flag : int, is_set : bool = true) -> int:
    if is_set:
        return byte | flag
    else:
        return byte & ~flag
AThousandShips commented 8 months ago

Thank you, will take a look

tlloancy commented 8 months ago

at first i thought i found a solution because when i sent, say [0, [1,2,3]] as an argument to the from_raw() function the result was [0,0]

but it was because of the signature. If i put func from_raw(arr : PackedByteArray):then any arr i send become empty. So it is now just func from_raw(arr)

tlloancy commented 8 months ago

error based on this work that i try to port to godot version 4 Messages MatchMakerServer

these two links above are the same files but in godot3

AThousandShips commented 8 months ago

That probably means you're not recieving a PackedByteArray which probably explains things

Nite that get_data returns Array so it's not certain it actually provides a PackedByteArray compatible type

tlloancy commented 8 months ago

Ok so if the type passed is wrong that throws no error but simply empty the value right ? So by retiring the type i probably accept a simple array that can't be decoded right ? So this means i cant for example cast an Array to PackedByteArray

This is why i'm unsure if what i do is right or if i have to use websocket peer i don't know what i'm doing

AThousandShips commented 8 months ago

No it tries to convert it, might break

I'd suggest checking for errors on put_data, you might send invalid data

I think you might be breaking things with your setup, I'd suggest making sure that data is correctly sent in the first place, send test data and check what comes through

tlloancy commented 8 months ago

So i leave from_raw(arr) as it is or from_raw(arr : PackedByteArray) ?

what i feed put_data with pass always here :

func get_raw() -> PackedByteArray:
    var message = PackedByteArray()

    var byte = 0
    byte = set_bit(byte, SERVER_LOGIN, server_login)
    byte = set_bit(byte, IS_ECHO, is_echo)
    byte = set_bit(byte, MATCH_START, match_start)
    byte = set_bit(byte, DISCONNECTED_CLOSED, disconnected_closed)
    byte = set_bit(byte, DISCONNECTED_DISCONNECTED, disconnected_disconnected)
    byte = set_bit(byte, MATCH_SIZE, match_size)

    message.append(byte)
    message.append_array(var_to_bytes_with_objects(content))

    return message
AThousandShips commented 8 months ago

Please check that the data you are sending works right, that's the first step

AThousandShips commented 8 months ago

For example check errors at: spTCP.put_data(message.get_raw())

tlloancy commented 8 months ago

Ok thanks

tlloancy commented 8 months ago

To be sure : You mean that i don't need any websocketpeer to communicate ? streampeertcp is enough ? this is to know if i can revert back this part:


            var wsp = WebSocketPeer.new()
            wsp.accept_stream(spTCP)
            wsp.poll()
            var status = wsp.get_ready_state()
            if status == WebSocketPeer.STATE_OPEN:
                while wsp.get_available_packet_count():
                    _on_data(buf, wsp, _conn)
            #while true:
            #   buf = _conn.get_available_bytes()
            #   if buf <= 0:
            #       break
            #   _on_data(buf, _conn)```
AThousandShips commented 8 months ago

That's not what I mean? I mean: Make sure the data is sent correctly, and check for example what spTCP.put_data(message.get_raw()) returns, it returns Error, make sure it returns OK

Because if the data that is sent isn't correct, then the issue isn't with the decoding, understand?

Send the data, and compare the input and output

Also check that msg.from_raw(msg.get_raw()) works correctly

Essentially what I'm asking is: Make sure you are having a bug where you think you have, I don't know that that's the issue, I suspect you're either seeing some data issues, or using the network features incorrectly

I am not able to test this myself right now though, but my suggestion would be to send some packet, and check that the input and output data match, and that the put_data method also yields the correct results, I don't know that this works the way you might think but I'm not sure

tlloancy commented 8 months ago

what lead me in the wrong way first is that : PackedByteArray get_data ( ) const But i didn't know i was in the wrong page : https://docs.godotengine.org/en/stable/classes/class_image.html

get_data() do return an array although put_data takes a PackedByteArray. This is why i needed to know if i communicate the wrong way with streampeerTCP instead of WebsocketPeer. Because this is obvious it would be the cause of the decode fail.

[edit] the Websocketpeer method get_packet do return a PackedByteArray whereas get_data spTCP returns array

AThousandShips commented 8 months ago

I don't think you can connect correctly with a TCPServer and WebSocketPeer, the later likely uses a code format that means you get garbled data, I'd suggest using WebSocket or TCP on both ends to ensure

I'm about to leave (the computer) for the day and can look more into this tomorrow if you don't figure it out by yourself by then 😃

tlloancy commented 8 months ago

i will try that

tlloancy commented 8 months ago

thanks :D

tlloancy commented 8 months ago

I used WebSocketPeer and it works ! there's some progress ! but now on client side i have :


          at: RTC_Client.initialize (res://MultiplayerFramework/WebRTCClient.gd:23)
RTC Creating peer for <WebSocketPeer#-9223371987026443096>
WARNING: No default WebRTC extension configured.
     at: create (modules/webrtc/webrtc_peer_connection.cpp:51)
ERROR: Required virtual method WebRTCPeerConnectionExtension::_initialize must be overridden before calling.
   at: _gdvirtual__initialize_call (modules/webrtc/webrtc_peer_connection_extension.h:52)
ERROR: Condition "network_mode == MODE_NONE" is true. Returning: ERR_UNCONFIGURED
   at: add_peer (modules/webrtc/webrtc_multiplayer_peer.cpp:292)
SCRIPT ERROR: Invalid type in function 'add_peer' in base 'WebRTCMultiplayerPeer'. Cannot convert argument 2 from Object to int.
          at: RTC_Client.create_peer (res://MultiplayerFramework/WebRTCClient.gd:68)```

seems like there's still some updates to do
tlloancy commented 8 months ago

[edit] ok this one is solved by that https://www.reddit.com/r/godot/comments/16c0f2a/creating_webrtcpeerconnection_causes_init_error/

last update: E 0:00:08:0129 WebRTCClient.gd:54 @ create_peer(): Required virtual method WebRTCPeerConnectionExtension::_initialize must be overridden before calling.

where i give ice servers infos:


var peer: WebRTCPeerConnection = WebRTCPeerConnection.new()
    peer.initialize({
        "iceServers": [ 
tlloancy commented 8 months ago

just reporting some strange error i got on server side

ERROR: Not enough response headers, got: 3, expected >= 4.
   at: _parse_client_request (modules/websocket/wsl_peer.cpp:154)
Godot Engine v4.1.2.stable.official.399c9dc39 - https://godotengine.org

it happened only one time

tlloancy commented 8 months ago

yep i got a bunch of debug now

2023-11-03 04:04:27.170 INFO  [24300] [rtc::impl::IceTransport::LogCallback@362] juice: Using TURN server turn.deter-mi.net:3478
2023-11-03 04:04:27.197 INFO  [24300] [rtc::impl::IceTransport::LogCallback@362] juice: Using STUN server stun2.deter-mi.net:3479
2023-11-03 04:04:27.199 INFO  [3528] [rtc::impl::IceTransport::LogCallback@362] juice: Changing state to connecting
2023-11-03 04:04:27.199 INFO  [3528] [rtc::impl::PeerConnection::changeIceState@1197] Changed ICE state to checking
2023-11-03 04:04:27.200 INFO  [3528] [rtc::impl::PeerConnection::changeState@1179] Changed state to connecting
created o2023-11-03 04:04:27.201 INFO  [2852] [rtc::impl::IceTransport::LogCallback@362] juice: Using TURN server turn.deter-mi.net:3478
ffer
2023-11-03 04:04:27.202 INFO  [2852] [rtc::impl::IceTransport::LogCallback@362] juice: Using STUN server stun2.deter-mi.net:3479
On message: { "id": 217829720, "offer": "v=0\r\no=rtc 3234038252 0 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE 0\r\na=msid-semantic:WMS *\r\na=setup:actpass\r\na=ice-ufrag:677E\r\na=ice-pwd:x5TSrDtPL9VVXZphXEBLPG\r\na=ice-options:ice2,trickle\r\na=fingerprint:sha-256 1C:4E:9E:BF:31:15:0F:AC:87:B3:67:8D:A1:50:D3:DB:56:B6:2D:3E:84:8A:4E:82:9B:37:03:A4:C3:79:EB:0E\r\nm=application 9 UDP/DTLS/SCTP webrtc-datachannel\r\nc=IN IP4 0.0.0.0\r\na=mid:0\r\na=sendrecv\r\na=sctp-port:5000\r\na=max-message-size:262144\r\n" }
Got offer: 217829720
On message: { "id": 217829720, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:6 1 UDP 2130705151 2001:861:51c6:48f0:28da:1dfa:4e82:c856 51146 typ host" } }
On message: { "id": 217829720, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:1 1 UDP 2122317823 192.168.56.1 51146 typ host" } }
On message: { "id": 217829720, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:2 1 UDP 2122317567 192.168.1.76 51146 typ host" } }
On message: { "id": 217829720, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:3 1 UD2023-11-03 04:04:27.322 INFO  [3588] [rtc::impl::IceTransport::LogCallback@362] juice: Got STUN mapped address 89.82.241.180:51146 from TURN server
P 2023-11-03 04:04:27.323 INFO  [3588] [rtc::impl::IceTransport::LogCallback@362] juice: Allocated TURN relayed address 139.162.181.161:49096
2122317311 192.168.2.1 51146 typ host" } }
On message: { "id": 217829720, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:4 1 UDP 2122317055 192.168.153.1 51146 typ host" } }
On message: { "id": 217829720, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:5 1 UDP 2122316799 172.21.32.1 51146 typ host" } }
On message: { "id": 217829720, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:7 1 UDP 1686108671 89.82.241.180 51146 typ srflx raddr 0.0.0.0 rport 0" } }
On message: { "id": 217829720, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:8 1 UDP 8386815 139.162.181.161 49096 typ relay raddr 0.0.0.0 rport 0" } }
2023-11-03 04:04:50.759 INFO  [3588] [rtc::impl::IceTransport::LogCallback@362] juice: STUN server binding failed
2023-11-03 04:04:50.759 INFO  [3588] [rtc::impl::IceTransport::LogCallback@362] juice: Candidate gathering done
2023-11-03 04:04:50.759 INFO  [3588] [rtc::impl::PeerConnection::changeGatheringState@1215] Changed gathering state to complete

But apparently my peers don't connect each other anymore

i Replaced WebRtcMultiplayer.initialize by WebRtcMultiplayerPeer.create_mesh but no luck at the moment

tlloancy commented 8 months ago

i tryed create_client instead instead of create_mesh. More verbose but still no connection between the peers

Logged in with id 55621678
On message: 55621678
Match started as player 0
RTC Creating peer for 944633828
2023-11-03 04:36:43.170 DEBUG [27744] [rtc::impl::Init::doInit@113] Global initialization
2023-11-03 04:36:43.170 DEBUG [27744] [rtc::impl::Init::doInit@123] Spawning 12 threads
2023-11-03 04:36:43.178 DEBUG [23840] [rtc::impl::Certificate::Generate@380] Generating certificate (OpenSSL)
2023-11-03 04:36:43.178 DEBUG [26736] [rtc::impl::Certificate::Generate@380] Generating certificate (OpenSSL)
2023-11-03 04:36:43.178 INFO  [27744] [rtc::impl::PeerConnection::changeIceState@1197] Changed ICE state to closed
2023-11-03 04:36:43.179 INFO  [27744] [rtc::impl::PeerConnection::changeState@1179] Changed state to closed
2023-11-03 04:36:43.180 DEBUG [27744] [rtc::impl::IceTransport::IceTransport@57] Initializing ICE transport (libjuice)
2023-11-03 04:36:43.181 INFO  [27744] [rtc::impl::IceTransport::IceTransport@112] Using STUN server "stun2.deter-mi.net:3479"
2023-11-03 04:36:43.183 INFO  [27744] [rtc::impl::IceTransport::IceTransport@128] Using TURN server "turn.deter-mi.net:3478"
2023-11-03 04:36:43.183 DEBUG [27744] [rtc::impl::PeerConnection::processLocalDescription@956] Adding application to local description, mid="0"
2023-11-03 04:36:43.184 INFO  [27744] [rtc::impl::PeerConnection::changeSignalingState@1228] Changed signaling state to have-local-offer
2023-11-03 04:36:43.184 INFO  [27744] [rtc::impl::PeerConnection::changeGatheringState@1215] Changed gathering state to in-progress
2023-11-03 04:36:43.185 INFO  [27744] [rtc::impl::IceTransport::LogCallback@362] juice: Changing state to gathering
2023-11-03 04:36:43.189 INFO  [27744] [rtc::impl::IceTransport::LogCallback@362] juice: Changing state to connecting
2023-11-03 04:36:43.190 INFO  [27744] [rtc::impl::PeerConnection::changeIceState@1197] Changed ICE state to checking
2023-11-03 04:36:43.190 INFO  [27744] [rtc::impl::PeerConnection::changeState@1179] Changed state to connecting
Match started as player 0
RTC Creating peer for 944633828
2023-11-03 04:36:43.195 DEBUG [23840] [rtc::impl::Certificate::Generate@380] Generating certificate (OpenSSL)
2023-11-03 04:36:43.195 INFO  [27744] [rtc::impl::PeerConnection::changeIceState@1197] Changed ICE state to closed
2023-11-03 04:36:43.195 DEBUG [19204] [rtc::impl::Certificate::Generate@380] Generating certificate (OpenSSL)
2023-11-03 04:36:43.195 INFO  [27744] [rtc::impl::PeerConnection::changeState@1179] Changed state to closed
2023-11-03 04:36:43.198 INFO  [27744] [rtc::impl::PeerConnection::changeIceState@1197] Changed ICE state to closed
2023-11-03 04:36:43.199 INFO  [27744] [rtc::impl::PeerConnection::changeState@1179] Changed state to closed
2023-11-03 04:36:43.199 DEBUG [27744] [rtc::impl::IceTransport::IceTransport@57] Initializing ICE transport (libjuice)
2023-11-03 04:36:43.199 INFO  [27744] [rtc::impl::IceTransport::IceTransport@112] Using STUN server "stun.deter-mi.net:3478"
2023-11-03 04:36:43.199 INFO  [27744] [rtc::impl::IceTransport::IceTransport@128] Using TURN server "turn.deter-mi.net:3478"
2023-11-03 04:36:43.199 DEBUG [2504] [rtc::impl::IceTransport::~IceTransport@159] Destroying ICE transport
2023-11-03 04:36:43.200 DEBUG [27744] [rtc::impl::PeerConnection::processLocalDescription@956] Adding application to local description, mid="0"
2023-11-03 04:36:43.201 INFO  [27744] [rtc::impl::PeerConnection::changeSignalingState@1228] Changed signaling state to have-local-offer
2023-11-03 04:36:43.201 INFO  [27744] [rtc::impl::PeerConnection::changeGatheringState@1215] Changed gathering state to in-progress
2023-11-03 04:36:43.202 INFO  [27744] [rtc::impl::IceTransport::LogCallback@362] juice: Changing state to gathering
2023-11-03 04:36:43.217 INFO  [8572] [rtc::impl::IceTransport::LogCallback@362] juice: Using TURN server turn.deter-mi.net:3478
2023-11-03 04:36:43.244 INFO  [8572] [rtc::impl::IceTransport::LogCallback@362] juice: Using STUN server stun2.deter-mi.net:3479
2023-11-03 04:36:43.245 INFO  [27744] [rtc::impl::IceTransport::LogCallback@362] juice: Changing state to connecting
2023-11-03 04:36:43.245 INFO  [27744] [rtc::impl::PeerConnection::changeIceState@1197] Changed ICE state to checking
2023-11-03 04:36:43.248 INFO  [27744] [rtc::impl::PeerConnection::changeState@1179] Changed state to connecting
2023-11-03 04:36:43.249 INFO  [27544] [rtc::impl::IceTransport::LogCallback@362] juice: Using TURN server turn.deter-mi.net:3478
2023-11-03 04:36:43.278 INFO  [27544] [rtc::impl::IceTransport::LogCallback@362] juice: Using STUN server stun.deter-mi.net:3478
2023-11-03 04:36:43.341 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: STUN server binding successful
2023-11-03 04:36:43.342 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Got STUN mapped address 2001:861:51c6:48f0:fc8f:cf9b:4e83:23c:58004 from server
On message: { "id": 55621678, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:6 1 UDP 2130705151 2001:861:51c6:48f0:28da:1dfa:4e82:c856 58004 typ host" } }
On message: { "id": 55621678, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:1 1 UDP 2122317823 192.168.56.1 58004 typ host" } }
O2023-11-03 04:36:43.388 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: STUN server binding successful
n2023-11-03 04:36:43.388 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Got STUN mapped address 89.82.241.180:58004 from server
 message: { "id": 55621678, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:2 1 UDP 2122317567 192.168.1.76 58004 typ host" } }
On message: { "id": 55621678, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:3 1 UDP 2122317311 192.168.2.1 58004 typ host" } }
On message: { "id": 55621678, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:4 1 UDP 2122317055 192.168.153.1 58004 typ host" } }
On message: { "id": 55621678, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:5 1 UDP 2122316799 172.21.32.1 58004 typ host" } }
2023-11-03 04:36:43.438 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Got STUN mapped address 89.82.241.180:58004 from TURN server
2023-11-03 04:36:43.438 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Allocated TURN relayed address 139.162.181.161:44476
2023-11-03 04:36:43.439 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Candidate gathering done
2023-11-03 04:36:43.439 INFO  [27348] [rtc::impl::PeerConnection::changeGatheringState@1215] Changed gathering state to complete
On message: { "id": 55621678, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:7 1 UDP 1694497279 2001:861:51c6:48f0:fc8f:cf9b:4e83:23c 58004 typ srflx raddr 0.0.0.0 rport 0" } }
On message: { "id": 55621678, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:8 1 UDP 1686108415 89.82.241.180 58004 typ srflx raddr 0.0.0.0 rport 0" } }
On message: { "id": 55621678, "candidate": { "mid": "0", "index": 0, "sdp": "candidate:9 1 UDP 8386559 139.162.181.161 44476 typ relay raddr 0.0.0.0 rport 0" } }
2023-11-03 04:36:58.358 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: STUN server binding successful
2023-11-03 04:36:58.359 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Got STUN mapped address 2001:861:51c6:48f0:fc8f:cf9b:4e83:23c:58004 from server
2023-11-03 04:36:58.418 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: STUN server binding successful
2023-11-03 04:36:58.420 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Got STUN mapped address 89.82.241.180:58004 from server
2023-11-03 04:37:13.399 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: STUN server binding successful
2023-11-03 04:37:13.400 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Got STUN mapped address 2001:861:51c6:48f0:fc8f:cf9b:4e83:23c:58004 from server
2023-11-03 04:37:13.447 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: STUN server binding successful
2023-11-03 04:37:13.448 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Got STUN mapped address 89.82.241.180:58004 from server
2023-11-03 04:37:28.429 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: STUN server binding successful
2023-11-03 04:37:28.433 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Got STUN mapped address 2001:861:51c6:48f0:fc8f:cf9b:4e83:23c:58004 from server
2023-11-03 04:37:28.477 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: STUN server binding successful
2023-11-03 04:37:28.481 INFO  [27348] [rtc::impl::IceTransport::LogCallback@362] juice: Got STUN mapped address 89.82.241.180:58004 from server
tlloancy commented 8 months ago

And sometimes i get flat out this

Logged in with id 366766668
On message: 366766668
Match started as player -1
RTC Creating peer for 91896006
2023-11-03 05:03:17.764 DEBUG [13300] [rtc::impl::Init::doInit@113] Global initialization
2023-11-03 05:03:17.764 DEBUG [13300] [rtc::impl::Init::doInit@123] Spawning 12 threads
2023-11-03 05:03:17.773 DEBUG [13448] [rtc::impl::Certificate::Generate@380] Generating certificate (OpenSSL)
2023-11-03 05:03:17.773 DEBUG [20192] [rtc::impl::Certificate::Generate@380] Generating certificate (OpenSSL)
2023-11-03 05:03:17.773 INFO  [13300] [rtc::impl::PeerConnection::changeIceState@1197] Changed ICE state to closed
2023-11-03 05:03:17.777 INFO  [13300] [rtc::impl::PeerConnection::changeState@1179] Changed state to closed
Match started as player -1
RTC Creating peer for 91896006
2023-11-03 05:03:17.784 DEBUG [14544] [rtc::impl::Certificate::Generate@380] Generating certificate (OpenSSL)
2023-11-03 05:03:17.784 DEBUG [23200] [rtc::impl::Certificate::Generate@380] Generating certificate (OpenSSL)
2023-11-03 05:03:17.784 INFO  [13300] [rtc::impl::PeerConnection::changeIceState@1197] Changed ICE state to closed
2023-11-03 05:03:17.786 INFO  [13300] [rtc::impl::PeerConnection::changeState@1179] Changed state to closed
2023-11-03 05:03:17.787 INFO  [13300] [rtc::impl::PeerConnection::changeIceState@1197] Changed ICE state to closed
2023-11-03 05:03:17.789 INFO  [13300] [rtc::impl::PeerConnection::changeState@1179] Changed state to closed
tlloancy commented 8 months ago

just reporting some strange error i got on server side

ERROR: Not enough response headers, got: 3, expected >= 4.
   at: _parse_client_request (modules/websocket/wsl_peer.cpp:154)
Godot Engine v4.1.2.stable.official.399c9dc39 - https://godotengine.org

it happened only one time

Got this error again ?! crashed the whole server

AThousandShips commented 8 months ago

Sounds like your issue is network related then, unable to investigate right now but will take a deeper look when I'm able

However I'd say that this issue might be the wrong place to identify the network side and you should see if you can find related network issues and check the documentation and details for setting things up correctly

To verify that this isn't an issue with the decoding please test:

var msg1 := Message.new()
# setup a valid message
var data := msg1.get_raw()
var msg2 := Message.new()
msg2.from_raw(data)
# verify it is correct

If it works I'd say this issue is off the mark and something with the network is broken, either in your configuration or use of it, or a genuine bug, I'd say to continue to investigate that and if it is a bug open an issue for that, as I can't see any reason to think this is related to the encoding/decoding

tlloancy commented 8 months ago

have now this bunch of errors when i quit the app but i think these errors i get are related to another topic now. Thanks

ERROR: BUG: Unreferenced static string to 0: Physics2DConstraintSolveIslands
   at: unref (core/string/string_name.cpp:129)
ERROR: BUG: Unreferenced static string to 0: Physics2DConstraintSetup
   at: unref (core/string/string_name.cpp:129)
ERROR: BUG: Unreferenced static string to 0: @export
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: @export_multiline
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: @export_range
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: @warning_ignore
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: @icon
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: Variant
   at: unref (core/string/string_name.cpp:129)
ERROR: Pages in use exist at exit in PagedAllocator: N7Variant5Pools11BucketLargeE
   at: ~PagedAllocator (./core/templates/paged_allocator.h:170)
ERROR: Pages in use exist at exit in PagedAllocator: N7Variant5Pools12BucketMediumE
   at: ~PagedAllocator (./core/templates/paged_allocator.h:170)
ERROR: Pages in use exist at exit in PagedAllocator: N7Variant5Pools11BucketSmallE
   at: ~PagedAllocator (./core/templates/paged_allocator.h:170)
ERROR: BUG: Unreferenced static string to 0: GodotPhysicsDirectSpaceState2D
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: interface_added
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: gui_focus_changed
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: frame_pre_draw
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: frame_post_draw
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: SceneReplicationInterface
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: AudioEffectRecordInstance
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: process_frame
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: physics_frame
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: SceneCacheInterface
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: SceneRPCInterface
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: fallback_changed
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: button_down
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: button_up
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: child_exiting_tree
   at: unref (core/string/string_name.cpp:131)
ERROR: BUG: Unreferenced static string to 0: child_entered_tree
   at: unref (core/string/string_name.cpp:131)