jk, just continue to build ontop (added better debug prints, colors, bitstream additions, continuation for bitstream parsing, and currently working on acks)

This commit is contained in:
Emily 2021-05-10 22:45:41 +02:00
parent 4812d9c35d
commit c258c520a5
10 changed files with 503 additions and 130 deletions

View File

@ -3,7 +3,6 @@
"logging": {
"filename": "",
"level": "DEBUG",
"format": "[%(name)s:L%(lineno)02d %(levelname)s] %(message)s",
"datefmt": "%d-%b-%y %H:%M:%S"
}
},

View File

@ -7,6 +7,6 @@
0x1F ID_NO_FREE_INCOMING_CONNECTIONS
0x24 ID_CONNECTION_BANNED
0x25 ID_INVALID_PASSWORD
0x26 ID_MODIFIED_PACKET
0x27 ID_PONG
0x37 ID_ADVERTISE_SYSTEM
0x26 ID_MODIFIED_PACKET

View File

@ -1,3 +1,5 @@
from . import helpers
from . import server
from . import client

View File

@ -1,10 +1,12 @@
import socket
import struct
from time import time_ns
from .base import BaseClient
from ..raknet.bitstream import Bitstream
import logging
from ..helpers import logging
logger = logging.getLogger(__name__)
STATE_CONNECTING = 0
@ -12,6 +14,9 @@ STATE_CONNECTED = 1
class PlayerClient(BaseClient):
ranges = []
resend_list = dict()
def __init__(self, server: "__ServerInstance__", ip: str, port: int):
super().__init__(server, ip, port)
logger.debug("Client resolved to PlayerClient")
@ -74,50 +79,112 @@ class PlayerClient(BaseClient):
async def on_player_packet(self, packet: bytes):
bitstream = Bitstream(packet)
time = time_ns()
_, has_acks = bitstream.read_bit()
if has_acks:
logger.debug("Unfinished code hit; has_acks: True")
return
#logger.debug("Unfinished code hit; has_acks: True")
await self.handle_acknowledgement(bitstream, time)
#return
handled = await self.handle_internal_packet(bitstream)
if not handled:
logger.debug("Internal packet were not handled")
async def handle_internal_packet(self, bitstream: Bitstream) -> bool:
if (bitstream.length * 8) - bitstream.offset < 0x10:
async def handle_acknowledgement(self, bitstream: Bitstream, time: int) -> bool:
if not self.deserialize(bitstream):
return False
for i in range(len(self.ranges)):
min, max = self.ranges[i][0], self.ranges[i][1]
if min > max:
return False
for i in range(min, max + 1, 1):
acked_histogram_counter = self.remove_packet_from_resend_list_and_delete_older_reliable_sequence()
def deserialize(self, bitstream: Bitstream): # TODO: Something weird with range thing DS_RangeList.h@L92
self.ranges.clear()
success, count = bitstream.read_compressed(0x10, True)
if not success:
return False
_, message_number = bitstream.read(0x10)
_, reliability = bitstream.read_int(0x04)
count, = struct.unpack(b"<H", count)
min, max = 0, 0
for i in range(count):
_, max_equal_to_min = bitstream.read_bit()
success, min = bitstream.read_bits(0x10)
if not success:
return False
min, = struct.unpack(b"<H", min)
if not max_equal_to_min:
success, max = bitstream.read_bits(0x10)
if not success:
return False
max, = struct.unpack(b"<H", max)
if max < min:
return False
else:
max = min
self.ranges.append((min, max))
return True
def remove_packet_from_resend_list_and_delete_older_reliable_sequence(self, message_number: int, time: int):
return 0 # TODO
async def handle_internal_packet(self, bitstream: Bitstream) -> bool:
if bitstream.length - bitstream.offset < 0x10:
return False
_, message_number = bitstream.read_bits(0x10)
_, reliability = bitstream.read_bits(0x04)
if reliability in (7, 9, 10):
success, ordering_channel = bitstream.read_int(0x05)
if success == False:
success, ordering_channel = bitstream.read_bits(0x05)
if not success:
return False
success, ordering_index = bitstream.read_int(0x10)
if success == False:
success, ordering_index = bitstream.read_bits(0x10)
if not success:
return False
_, is_split_packet = bitstream.read_bit()
_, is_split_packet = bitstream.read_bit()
if is_split_packet:
logger.warning("Skipping split packet")
return
# TODO: set global split_packet index and count back to 0
# Something I dont understand yet
# TODO: ReadCompressed
#bitstream.offset += 1
_, data = bitstream.read_compressed(0x10, True)
_, unknown = bitstream.read(0x01)
_, bit_length = bitstream.read(0x08)
success, data_bit_length = bitstream.read_compressed(0x10, True)
if not success:
return False
#_, unknown = bitstream.read(0x01)
#_, bit_length = bitstream.read(0x08)
##
logger.debug("bit_length: %d" % bit_length)
logger.debug("bitstream: %s" % bitstream)
#logger.debug("bit_length: %d" % bit_length)
#logger.debug("bitstream: %s" % bitstream)
data_bit_length, = struct.unpack(b"<H", data_bit_length)
# TODO: ReadAlignedBytes
_, data = bitstream.read(bit_length)
#_, data = bitstream.read(bit_length)
_, data = bitstream.read_aligned_bytes((data_bit_length + 7) >> 3)
logger.debug("data: %s" % data)
return await self.handle_packet(data)
async def handle_packet(self, packet: bytes):
if packet[0] == 0x0B: # ID_CONNECTION_REQUEST
pass # TODO: Send ack and data after
return False

View File

@ -3,7 +3,6 @@
"logging": {
"filename": "",
"level": "DEBUG",
"format": "[%(name)s:L%(lineno)02d %(levelname)s] %(message)s",
"datefmt": "%d-%b-%y %H:%M:%S"
}
},

View File

@ -0,0 +1 @@
from . import logging

62
sampy/helpers/logging.py Normal file
View File

@ -0,0 +1,62 @@
import sys
import logging
from logging import *
if sys.platform == 'win32':
import colorama
colorama.init()
FORMAT_STR_NORMAL = "%(levelname)s \x1b[33;1m%(asctime)s.%(msecs)03d \x1b[30;1m|\x1b[0m %(message)s"
COLOR_RESET = 0
COLOR_BLACK = 30
COLOR_RED = 31
COLOR_GREEN = 32
COLOR_YELLOW = 33
COLOR_BLUE = 34
COLOR_PURPLE = 35
COLOR_CYAN = 36
COLOR_GRAY = 90
COLOR_PINK = 95
COLOR_PREFIX = "\x1b[%dm"
def color(color_code: int) -> str:
return COLOR_PREFIX % color_code
def init():
from ..shared import glob
COLORS = {
logging.CRITICAL: "31",
logging.FATAL: "31",
logging.ERROR: "31",
logging.WARNING: "33",
logging.INFO: "32",
logging.DEBUG: "35",
logging.NOTSET: "37",
}
for k,v in COLORS.items():
logging.addLevelName(k, "\x1b[%sm%s\x1b[0m" % (v, " " * (8 - len(logging.getLevelName(k))) + logging.getLevelName(k)))
conf = glob.conf["logging"]
default_logging_fallback = False
if type(conf["level"]) is not int:
try:
conf["level"] = getattr(logging, conf["level"])
except:
conf["level"] = logging.INFO
default_logging_fallback = True
logging_handlers = [logging.StreamHandler(sys.stdout)]
if len(conf["filename"]):
logging_handlers.append(logging.FileHandler(conf["filename"]))
del conf["filename"]
logging.basicConfig(**conf, format=FORMAT_STR_NORMAL, handlers = logging_handlers)
if default_logging_fallback:
logging.warning("Invalid logging value in config! Defaulting to logging level INFO.")
logging.info("Logging level: %d" % conf["level"])
logging.debug("Logger configured")

View File

@ -1,29 +1,109 @@
from __future__ import annotations
import ctypes as c
from array import array
from typing import Tuple, Union
import logging
from ..helpers import logging
logger = logging.getLogger(__name__)
DEBUG = (logger.root.level & logging.DEBUG) == 10
if DEBUG:
import inspect
BITS_TO_BYTES = lambda x: (((x)+7)>>3)
BYTES_TO_BITS = lambda x: ((x)<<3)
debug_wrapper_depth = 0
ignored_bits = []
class Bitstream:
def __init__(self, data: bytes = b""):
self._offset = 0
self._buffer = bytearray(data) # array("B", data)
def debug_wrapper(func):
def wrapper(self, *args, **kwargs):
if not DEBUG:
return func(self, *args, **kwargs)
global debug_wrapper_depth
#global ignored_bits
ignored_bits.clear()
curframe = inspect.currentframe()
calframe = inspect.getouterframes(curframe, 2)
#print(calframe)
copy = self.clone()
header_func = "%s%s" % (func.__name__, (*args, *kwargs))
header = " {BLUE}{header_func}{SPACE_FUNC}{CYAN}{caller}{SPACE_CALLER}{GREEN}{file}{YELLOW}@L{lineno}{RESET}".format(
header_func = header_func,
caller = calframe[1].function,
file = calframe[1].filename.split("\\")[-1],
lineno = calframe[1].lineno,
CYAN = logging.color(logging.COLOR_CYAN),
BLUE = logging.color(logging.COLOR_BLUE),
GREEN = logging.color(logging.COLOR_GREEN),
YELLOW = logging.color(logging.COLOR_YELLOW),
RESET = logging.color(logging.COLOR_RESET),
SPACE_FUNC = " " * (28 - len(header_func)),
SPACE_CALLER = " " * (32 - len(calframe[1].function)),
)
prefix = "%s%s%s" % (
logging.color(logging.COLOR_RED),
">" * debug_wrapper_depth,
logging.color(logging.COLOR_RESET)
)
logger.debug(prefix + header)
debug_wrapper_depth += 1
result = func(self, *args, **kwargs)
edits = self.debug_edits(copy)
debug_wrapper_depth -= 1
logger.debug(edits)
return result
return wrapper
@property
def offset(self) -> int:
return self._offset
@property
def length(self) -> int:
return len(self._buffer)
return len(self._buffer) << 3
def clone(self) -> Bitstream:
copy = Bitstream(self._buffer)
copy._offset = self._offset
return copy
def _can_access_bits(self, bits_to_access: int) -> bool:
return self._offset + bits_to_access <= len(self._buffer) << 3
def add_bits(self, bit_length: int):
if bit_length <= 0:
return
self._buffer.extend(b"\x00" * BITS_TO_BYTES(bit_length))
def align_read_to_byte_boundary(self):
if DEBUG:
ignored_from = self._offset
if self._offset:
self._offset += 8 - (((self._offset - 1) & 7) + 1)
if DEBUG:
ignored_bits.append((ignored_from, self._offset))
@debug_wrapper
def write_bit(self, value: bool) -> bool:
if not self._can_access_bits(1):
return False
@ -37,6 +117,7 @@ class Bitstream:
self._offset += 1
return True
@debug_wrapper
def read_bit(self) -> Tuple[bool, bool]:
if not self._can_access_bits(1):
return False, False
@ -47,6 +128,7 @@ class Bitstream:
self._offset += 1
return True, value > 0
@debug_wrapper
def write(self, value: bytes, bit_length: int) -> bool:
if not self._can_access_bits(bit_length):
return False
@ -79,6 +161,7 @@ class Bitstream:
return True
@debug_wrapper
def read_int(self, bit_length: int) -> Tuple[bool, int]:
if not self._can_access_bits(bit_length):
return False, 0
@ -111,6 +194,29 @@ class Bitstream:
success, value = self.read_int(bit_length)
return success, value.to_bytes((bit_length + 7) >> 3, "big") # bytes(value)
@debug_wrapper
def write_compressed(self, data: bytes, bit_length: int, unsigned: bool = True) -> bool:
current_byte = (bit_length >> 3) - 1
byte_match = 0 if unsigned else 0xFF
while current_byte > 0:
if data[current_byte] == byte_match:
self.write_bit(True)
else:
self.write_bit(False)
self.write_bits(data, (current_byte + 1) << 3, True)
return True
if (unsigned and data[current_byte] & 0xF0 == 0x00) or (not unsigned and data[current_byte] & 0xF0 == 0xF0):
self.write_bit(True)
self.write_bits(data[current_byte:], 4, True)
else:
self.write_bit(False)
self.write_bits(data[current_byte:], 8, True)
return True
@debug_wrapper
def read_compressed(self, bit_length: int, unsigned: bool = True) -> Tuple[bool, bytes]:
current_byte = (bit_length >> 3) - 1
@ -121,16 +227,16 @@ class Bitstream:
while current_byte > 0:
success, bit = self.read_bit()
if success == False: # Cannot read the bit (end of stream)
if not success: # Cannot read the bit (end of stream)
return False, out
if bit:
out[current_byte] = byte_match
current_byte -= 1
else:
success, data = self.read((current_byte + 1) << 3)
out[:current_byte] = data
if success == False:
success, data = self.read_bits((current_byte + 1) << 3, True)
out[:len(data)] = data
if not success:
return False, out
return True, out
@ -138,29 +244,145 @@ class Bitstream:
return False, out
success, bit = self.read_bit()
if success == False: # Cannot read the bit (end of stream)
if not success: # Cannot read the bit (end of stream)
return False, out
if bit:
success, data = self.read(4)
out[current_byte:current_byte + 4] = data
if success == False:
success, data = self.read_bits(4, True)
out[current_byte:((current_byte + 4) + 7) >> 3] = data
if not success:
return False, out
out[current_byte] |= half_byte_match # Maybe recheck this in BitStream.cpp@L617; We have to set the high 4 bits since these are set to 0 by ReadBits
else:
success, data = self.read(8)
success, data = self.read_bits(8, True)
out[current_byte:current_byte + 8] = data
if success == False:
if not success:
return False, out
return True, out
@debug_wrapper
def write_bits(self, data: bytes, bit_length: int, align_bits_to_right: bool = True) -> bool:
if bit_length <= 0:
return False
self.add_bits(bit_length) # TODO: Check if needed
bits_used_mod8 = self.offset & 7
offset = 0
while bit_length > 0:
byte = data[offset]
if bit_length < 8 and align_bits_to_right:
byte <<= 8 - bit_length
if bits_used_mod8 == 0:
self._buffer[self.offset >> 3] = byte
else:
self._buffer[self.offset >> 3] |= byte >> bits_used_mod8
if 8 - bits_used_mod8 < 8 and 8 - bits_used_mod8 < bit_length: # Eh.. why not bits_used_mod8 != 0?
self._buffer[(self.offset >> 3) + 1] = byte << (8 - bits_used_mod8)
if bit_length >= 8:
self._offset += 8
else:
self._offset += bit_length
bit_length -= 8
offset += 1
return True
@debug_wrapper
def read_bits(self, bit_length: int, align_bits_to_right: bool = True) -> Tuple[bool, bytes]:
if bit_length <= 0:
return False, b""
if not self._can_access_bits(bit_length):
return False, b""
out = bytearray(BITS_TO_BYTES(bit_length))
read_offset_mod8 = self._offset & 7
offset = 0
while bit_length > 0:
out[offset] |= (self._buffer[self._offset >> 3] << read_offset_mod8) & 255
if read_offset_mod8 > 0 and bit_length > 8 - read_offset_mod8:
out[offset] |= self._buffer[(self.offset >> 3) + 1] >> (8 - read_offset_mod8)
bit_length -= 8
if bit_length < 0:
if align_bits_to_right:
out[offset] >>= -bit_length
self._offset += 8 + bit_length
else:
self._offset += 8
offset += 1
return True, out
@debug_wrapper
def read_aligned_bytes(self, byte_length: int) -> Tuple[bool, bytes]:
if byte_length <= 0:
return False, b""
self.align_read_to_byte_boundary()
if self.offset + (byte_length << 3) > (len(self._buffer) << 3):
return False, b""
out = self._buffer[(self.offset >> 3):(self.offset >> 3) + byte_length]
self._offset += byte_length << 3
return True, out
def pretty(self) -> str:
b = bytearray(" " + " ".join(" ".join(format(c, "08b")) for c in self._buffer) + " ", "ascii")
m = self._offset * 2 + (self._offset >> 3) - (self._offset // (max(1, len(self._buffer)) * 8))
b[m] = 124
return b.decode()
def debug_edits(self, prev_state: Bitstream) -> str:
#logger.debug(self.pretty())
bits = [list(format(c, "08b")) for c in self._buffer]
prev_bits = [list(format(c, "08b")) for c in prev_state._buffer]
bits.append([])
start = prev_state._offset
end = self._offset
edits = {start: "P", end: "R"}
for s, e in ignored_bits:
t = [x for x in edits.keys() if x <= s]
if len(t):
edits[e] = edits[t[-1]]
else:
edits[e] = "R"
edits[s] = "S"
edits = sorted(edits.items())
edits.reverse()
for k, v in edits:
bits[k // 8][k % 8:k % 8] = v
#print(bits)
bits = " ".join("".join([y + " " if y in "01" else y for y in x]).strip() for x in bits)
bits = bits.replace("R", logging.color(logging.COLOR_RESET))
bits = bits.replace("P", logging.color(logging.COLOR_PINK))
bits = bits.replace("S", logging.color(logging.COLOR_RED))
return bits
def __repr__(self) -> str:
return "<Bitstream addr:0x%012x offset:%d len:%d>" % (id(self), self._offset, len(self._buffer) << 3)

View File

@ -2,7 +2,8 @@ import os
import sys
import json
import shutil
import logging
from ..helpers import logging
if not os.path.isfile("config.json"):
shutil.copyfile(os.path.join(*__package__.split(".")[:-1], "default_config.json"), "config.json")
@ -14,27 +15,4 @@ with open("config.json", "r") as f:
conf = config["sampy"]
conf_log = conf["logging"]
# Setup logger
## fix for logging level
default_logging_fallback = False
if type(conf_log["level"]) is not int:
try:
conf_log["level"] = getattr(logging, conf_log["level"])
except Exception:
conf_log["level"] = logging.INFO
default_logging_fallback = True
## logging settings
logging_handlers = [logging.StreamHandler(sys.stdout)]
if len(conf_log["filename"]):
logging_handlers.append(logging.FileHandler(conf_log["filename"]))
del conf_log["filename"]
logging.basicConfig(**conf_log, handlers = logging_handlers)
logger = logging.getLogger(__name__)
logger.debug("Configured logger")
if default_logging_fallback:
logger.warning("Invalid logging value in config! Defaulting to logging level INFO.")
logger.info("Logging level: %d" % conf_log["level"])
logging.init()

185
test.py
View File

@ -1,85 +1,128 @@
from sampy.raknet.bitstream import Bitstream
from sampy.client.player import PlayerClient
bitstream = Bitstream(b"\x00" * 4)
MAGIC_BYTES = b"\x01\xff\x02"
MAGIC_BITS = [int(bit) for bit in " ".join([format(byte, "08b") for byte in MAGIC_BYTES]) if bit in ("0", "1")]
fail = 0
import struct
def print_pretty(prefix, msg):
prefix += " " * (40 - len(prefix))
print(prefix, msg)
class Packet:
def __init__(self, data: bytes, is_client: bool):
self.data = data
self.is_client = is_client
self.bitstream = Bitstream(bytearray.fromhex(self.data))
def reset_bitstream():
bitstream._buffer = bytearray(b"\x00" * len(bitstream._buffer))
bitstream._offset = 0
PACKETS = [
Packet("18 69 69", True),
Packet("1a 18 be", False),
Packet("18 71 d7", True),
Packet("19 00", False),
Packet("00 00 43 80 0b", True),
Packet("e3 00 00", False),
Packet("00 00 42 98 0c 11 33 30 45 39 33 39 33 33 36 39 42 35 36 38 43 32 00", False)
]
def test_write_bit(var_bits):
global fail
print_pretty("<Test bitstream.write_bit:in>", bitstream.pretty())
for bit in var_bits:
if not bitstream.write_bit(bit):
print_pretty("<Test bitstream.write_bit>", "Failed")
fail += 1
print_pretty("<Test bitstream.write_bit:out>", bitstream.pretty())
#client = PlayerClient(None, "127.0.0.1", 7777)
#client.state = 1
def test_read_bit(var_compare_bits):
global fail
print_pretty("<Test bitstream.read_bit:in>", bitstream.pretty())
for bit in var_compare_bits:
ok, bit2 = bitstream.read_bit()
if not ok:
print_pretty("<Test bitstream.read_bit>", "Failed (ok)")
fail += 1
continue
if bit2 != bit:
print_pretty("<Test bitstream.read_bit>", "Failed (match)")
fail += 1
continue
print_pretty("<Test bitstream.read_bit:out>", bitstream.pretty())
def pbs(bitstream: Bitstream, prefix: str = ""):
print(prefix, bitstream.pretty())
def test_write(var_bytes):
global fail
print_pretty("<Test bitstream.write:in>", bitstream.pretty())
if not bitstream.write(var_bytes, len(var_bytes) << 3):
print_pretty("<Test bitstream.write>", "Failed")
fail += 1
print_pretty("<Test bitstream.write:out>", bitstream.pretty())
def deserialize(bitstream: Bitstream): # TODO: Something weird with range thing DS_RangeList.h@L92
success, count = bitstream.read_compressed(0x10, True)
if not success:
return False
def test_read(var_compare_bytes):
global fail
print_pretty("<Test bitstream.read:in>", bitstream.pretty())
ok, bytez = bitstream.read(len(var_compare_bytes) << 3)
if ok:
print(var_compare_bytes, bytez)
if bytez != var_compare_bytes:
print_pretty("<Test bitstream.read>", "Failed (match)")
fail += 1
else:
print_pretty("<Test bitstream.read>", "Failed (ok)")
fail += 1
print_pretty("<Test bitstream.read:out>", bitstream.pretty())
count, = struct.unpack(b"<H", count)
def test_rw_bit(offset):
bitstream._offset = offset
test_write_bit(MAGIC_BITS)
bitstream._offset = offset
test_read_bit(MAGIC_BITS)
min, max = 0, 0
for i in range(count):
_, max_equal_to_min = bitstream.read_bit()
success, min = bitstream.read_bits(0x10)
if not success:
return False
def test_rw_bytes(offset):
bitstream._offset = offset
test_write(MAGIC_BYTES)
bitstream._offset = offset
test_read(MAGIC_BYTES)
min, = struct.unpack(b"<H", min)
# Test all edges
for i in range(9):
reset_bitstream()
test_rw_bit(i)
if not max_equal_to_min:
success, max = bitstream.read_bits(0x10)
if not success:
return False
reset_bitstream()
max, = struct.unpack(b"<H", max)
for i in range(9):
reset_bitstream()
test_rw_bytes(i)
if max < min:
return False
else:
max = min
print("Failed: %d" % fail)
return True
def on_player_packet(packet: bytes):
bitstream = Bitstream(packet)
pbs(bitstream, "Created")
_, has_acks = bitstream.read_bit()
pbs(bitstream, "has_acks")
if has_acks:
print("has_acks: True")
if not deserialize(bitstream):
return False
return
handled = handle_internal_packet(bitstream)
if not handled:
print("Internal packet were not handled")
def handle_internal_packet(bitstream: Bitstream) -> bool:
if bitstream.length - bitstream.offset < 0x10:
return False
_, message_number = bitstream.read_bits(0x10)
pbs(bitstream, "message_number")
_, reliability = bitstream.read_bits(0x04)
pbs(bitstream, "reliability")
if reliability in (7, 9, 10):
success, ordering_channel = bitstream.read_bits(0x05)
pbs(bitstream, "ordering_channel")
if not success:
return False
success, ordering_index = bitstream.read_bits(0x10)
pbs(bitstream, "ordering_index")
if not success:
return False
_, is_split_packet = bitstream.read_bit()
pbs(bitstream, "is_split_packet")
if is_split_packet:
print("Skipping split packet")
return
# TODO: set global split_packet index and count back to 0
# Something I dont understand yet
# TODO: ReadCompressed
#bitstream.offset += 1
success, data_bit_length = bitstream.read_compressed(0x10, True)
pbs(bitstream, "data_bit_length")
if not success:
return False
#_, unknown = bitstream.read(0x01)
#_, bit_length = bitstream.read(0x08)
##
#logger.debug("bit_length: %d" % bit_length)
#logger.debug("bitstream: %s" % bitstream)
data_bit_length, = struct.unpack(b"<H", data_bit_length)
print("data_bit_length:", data_bit_length)
# TODO: ReadAlignedBytes
#_, data = bitstream.read(bit_length)
_, data = bitstream.read_aligned_bytes((data_bit_length + 7) >> 3)
pbs(bitstream, "data")
print("data: %s" % data)
on_player_packet(PACKETS[-2].bitstream._buffer)